open-rmf / rmf_ros2

Internal ROS infrastructure for RMF
Apache License 2.0
71 stars 57 forks source link

[Bug]: Robot doesn't create lift session with open door #314

Closed Vortex-TH closed 3 weeks ago

Vortex-TH commented 9 months ago

Before proceeding, is there an existing issue or discussion for this?

OS and version

Ubuntu 22.04

Open-RMF installation type

Binaries

Other Open-RMF installation methods

No response

Open-RMF version or commit hash

0.0.1-1jammy.20231206.081430

ROS distribution

Iron

ROS installation type

Binaries

Other ROS installation methods

No response

Package or library, if applicable

No response

Description of the bug

In our facility we have an agv lift that doesn't have a door on the first floor level, so in the Lift adapter API (using the lift adapter template), I set the door to always be open when the lift is currently at that floor, ready for the robot to move in or out.

This causes a problem, as the robot apparently expects a closed door and a lift session only is created when the door is initially closed. I could create a 'virtual door' that only 'opens' when there is a request, but 1. that doesn't represent the real state 2. requires the integration of some arbitrary triggers for door control depending on the robot

I'm not sure if this is already addressed in #310. Unfortunately I don't have the opportunity to test that, maybe someone can have a look at it.

Steps to reproduce the bug

  1. Launch RMF
  2. Launch Lift Adapter with Lift API that is configured to have a door open by default (when lift is on that floor level)
  3. Sent the robot to a waypoint on another floor level

Expected behavior

The robot should request a Lift session and move into the lift

Actual behavior

No lift session is created (the robot waits in front of the lift and nothing happens), even though the door is open.

Additional information or screenshots

No response

Vortex-TH commented 8 months ago

Also, lift sessions don't get terminated when there is a door that stays open (or no door at all) after reaching a floor level.

mxgrey commented 8 months ago

Sorry for not noticing this issue report sooner.

I'm a bit perplexed by the problem that you're describing. I'm looking through the source code and I don't see anywhere that requires the lift doors to ever be closed.

the robot apparently expects a closed door and a lift session only is created when the door is initially closed

Lift sessions are managed by the lift supervisor which has no expectation of the door being open or closed; it just forwards whatever is asked for by the fleet adapters.

The fleet adapter only ever requests the door to be opened. The assumption is that the lift door will automatically close when it needs to, so there's no need for us to explicitly command a closed door.

The workflow for lift usage is only blocked on waiting for the door to be open. We don't have any condition that waits for the door to be closed.

Waiting for a lift session to end doesn't check the door state at all.

I think there must be some other problem blocking the workflow for you. Could you recreate the issue and then run

$ ros2 topic echo lift_states
$ ros2 topic echo lift_requests
$ ros2 topic echo adapter_lift_requests

and let me know what messages come out of each?

Vortex-TH commented 8 months ago

Thanks for the reply. I hope I can narrow down the issue next week if I have some free time. I'll have a look if I added something that may cause this.

I remember there was some confusion about what to return for the value of destination_floor when the lift is idle at the floor, but I'm not sure if that was causing issues. I'll check.

I'm also not sure if the other issue I reported (and is reproducible in the sim) has an effect or is intended behaviour. Maybe you can have a look at that too.

Vortex-TH commented 8 months ago

I noticed that there seems to be an empty session that blocks the lift request by the robot:

[lift_supervisor-12] [INFO] [1705944941.145228398] [rmf_lift_supervisor]: [] Published lift request to [L1] from lift supervisor
[fleet_adapter_neo-14] [INFO] [1705944941.145494490] [neo_fleet_adapter]: [neo/neo_2] is waiting to begin a session with lift [MyLift] but the lift is currently held by []
[lift_supervisor-12] [INFO] [1705944941.145883701] [rmf_lift_supervisor]: [neo/neo_2] Received adapter lift request to [L1] with request type [1]
[lift_supervisor-12] [INFO] [1705944942.145425284] [rmf_lift_supervisor]: [] Published lift request to [L1] from lift supervisor
[fleet_adapter_neo-14] [INFO] [1705944942.145653706] [neo_fleet_adapter]: [neo/neo_2] is waiting to begin a session with lift [MyLift] but the lift is currently held by []
[lift_supervisor-12] [INFO] [1705944942.145969155] [rmf_lift_supervisor]: [neo/neo_2] Received adapter lift request to [L1] with request type [1]
[lift_supervisor-12] [INFO] [1705944943.146061729] [rmf_lift_supervisor]: [] Published lift request to [L1] from lift supervisor
[fleet_adapter_neo-14] [INFO] [1705944943.146403358] [neo_fleet_adapter]: [neo/neo_2] is waiting to begin a session with lift [MyLift] but the lift is currently held by []
[lift_supervisor-12] [INFO] [1705944943.146671500] [rmf_lift_supervisor]: [neo/neo_2] Received adapter lift request to [L1] with request type [1]
[lift_supervisor-12] [INFO] [1705944944.145847326] [rmf_lift_supervisor]: [] Published lift request to [L1] from lift supervisor
[fleet_adapter_neo-14] [INFO] [1705944944.146274891] [neo_fleet_adapter]: [neo/neo_2] is waiting to begin a session with lift [MyLift] but the lift is currently held by []
[lift_supervisor-12] [INFO] [1705944944.146552614] [rmf_lift_supervisor]: [neo/neo_2] Received adapter lift request to [L1] with request type [1]
[lift_supervisor-12] [INFO] [1705944945.148897978] [rmf_lift_supervisor]: [] Published lift request to [L1] from lift supervisor
[fleet_adapter_neo-14] [INFO] [1705944945.149180348] [neo_fleet_adapter]: [neo/neo_2] is waiting to begin a session with lift [MyLift] but the lift is currently held by []
[lift_supervisor-12] [INFO] [1705944945.149544510] [rmf_lift_supervisor]: [neo/neo_2] Received adapter lift request to [L1] with request type [1]

/lift_requests and /adapter_lift_requests look like this (published at 1Hz):

---
lift_name: MyLift
request_time:
  sec: 1705944943
  nanosec: 146480901
session_id: neo/neo_2
request_type: 1
destination_floor: L1
door_state: 2
---

or this:

---
lift_name: MyLift
request_time:
  sec: 1705945109
  nanosec: 452245532
session_id: ''
request_type: 0
destination_floor: L1
door_state: 0
---

/lift_states:

---
lift_time:
  sec: 1705945570
  nanosec: 316430784
lift_name: MyLift
available_floors:
- L1
- L2
current_floor: L1
destination_floor: L1
door_state: 2
motion_state: 0
available_modes:
- 1
- 2
current_mode: 2
session_id: ''
---
Vortex-TH commented 1 month ago

So, I did some more experiments (on real hardware) with a clean approach and captured some logs.

As for the setup, my lift now looks like this:

[ L3 ] [ L2 ] [ L1 ] <-- No door (= always open)

But for the tests, I only used L1 and L2.

For each test, I captured the following topics:

/lift_states /lift_requests /adapter_lift_requests

and also the output of my lift adapter.

Test 1: Idle lift in L1 --- [**/lift_states**](https://gist.github.com/Vortex-TH/9b8918069b1b4f72193ae5e07ef3e9c3) [**/lift_requests**](https://gist.github.com/Vortex-TH/cbbf83326105692b182bcb8ff752534e) **/adapter_lift_requests** empty **Liftadapter output** Forgot to save output, but probably looks similiar to Test 2 :) ---
Test 2: Idle lift in L2 --- [**/lift_states**](https://gist.github.com/Vortex-TH/3001ab285f4672e3488c1009b27beab2) [**/lift_requests**](https://gist.github.com/Vortex-TH/ef5eab8685185926af1c5dbd91af0de6) **/adapter_lift_requests** empty **Liftadapter output** ``` [INFO] [1723802857.968736468] [lift_adapter_template]: Checking connectivity. Elevator client connected. [INFO] [1723802858.010080737] [lift_adapter_template]: Initializing with status. Initial state: rmf_lift_msgs.msg.LiftState(lift_time=builtin_interfaces.msg.Time(sec=1723802858, nanosec=10292734), lift_name='MyLift', available_floors=['L1', 'L2', 'L3'], current_floor='L2', destination_floor='L2', door_state=, motion_state=, available_modes=[1, 2], current_mode=2, session_id='') [INFO] [1723802858.227493242] [lift_adapter_template]: Running LiftAdapterTemplate [INFO] [1723802859.453635121] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802860.455794868] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802861.446050072] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802862.450716855] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802863.463305613] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802864.456636370] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802865.451086139] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802866.456297985] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802867.451232224] [lift_adapter_template]: Requested lift to L2. [INFO] [1723802868.461929042] [lift_adapter_template]: Requested lift to L2. [KeyboardInterrupt] ``` ---
Test 3: Idle lift in L2, then request to L1 by Rviz panel --- [**/lift_states**](https://gist.github.com/Vortex-TH/7b9ef65f8a8229624906cf0be55e21b3) [**/lift_requests**](https://gist.github.com/Vortex-TH/694cd4d1f61bead5d6fd00d1683e4dc7) **/adapter_lift_requests** ``` lift_name: MyLift request_time: sec: 1723803591 nanosec: 446226334 session_id: lift_panel_session request_type: 1 destination_floor: L1 door_state: 2 --- [KeyboardInterrupt] ``` [**Liftadapter output**](https://gist.github.com/Vortex-TH/dfd1286865e8021e5a20a4691f212b2c) **Observation** The lift moves from L2 to L1 as requested from the lift panel in Rviz. ---
Test 4: Idle lift in L2, then request by AGV from L1 --- [**/lift_states**](https://gist.github.com/Vortex-TH/39055745a9eb1fdd6a672277d0615fcc) [**/lift_requests**](https://gist.github.com/Vortex-TH/0cfbce24f5d89dc8c3d035a967c40161) [**/adapter_lift_requests**](https://gist.github.com/Vortex-TH/e2349dee4dca907b09b28dbd2e73120b) [**Liftadapter output**](https://gist.github.com/Vortex-TH/03ff0b20b2e0f6238684930294350c05) **Observation** The lift moves from L2 to L1, the AGV moves in to the lift, which then moves to L2. The AGV then doesn't leave the lift, but that may be another issue caused by a faulty localization or something which I will address later. ---
Test 5: Idle lift in L1, then request by AGV from L1 --- [**/lift_states**](https://gist.github.com/Vortex-TH/18ee5dad8a09c11c64bd0726ae9ef559) [**/lift_requests**](https://gist.github.com/Vortex-TH/7e8b4bee4a3b68137b193d5edf4d48ef) **/adapter_lift_requests** ``` lift_name: MyLift request_time: sec: 1723810271 nanosec: 677284008 session_id: neo/neo_1 request_type: 1 destination_floor: L1 door_state: 2 --- [KeyboardInterrupt] ``` [**Liftadapter output**](https://gist.github.com/Vortex-TH/9d6c386f875224dd9e2f2156e80956fe) **Observation** The AGV moves in front of the lift, but then nothing happens, although the lift is ready for it to move in. ---

Results

I think Test 1 to 4 worked as they should, although I may have noticed a problem in Test 1 which could have caused Test 5 to fail:

When the lift is in L1, RMF repeatedly requests it to L1 with door_state 0 (closed), which is never going to be achieved since the door is always open. Could this have the effect that there is a session that doesn't get released and thus the AGV doesn't move into the lift?

xiyuoh commented 1 month ago

Hello @Vortex-TH ! Thank you for the logs, they're very helpful to understand what is going on with these lift sessions. I just wanted to clarify about Tests 4 and 5:

Test 4: Is the objective of Test 4 (a) to see if the AGV can command the lift to enter, then end the lift session, or (b) to see if the AGV can travel from L1 to L2? I notice that the lift is being requested from L2 to L1 by the AGV so that the AGV could enter. May I check if there was a request by the user for the lift to go to L2 after the robot has entered the lift, or did the lift request to L2 come out of nowhere? Mainly curious about where these LiftRequests came from.

Test 5: What are the logs on RMF fleet adapter when the lift is ready and doors opened on L1 for the robot to move in?

Vortex-TH commented 1 month ago

Test 4: Is the objective of Test 4 (a) to see if the AGV can command the lift to enter, then end the lift session, or (b) to see if the AGV can travel from L1 to L2?

I want to see whether the AGV can enter and then goes from L1 to L2, which it did.

I notice that the lift is being requested from L2 to L1 by the AGV so that the AGV could enter. May I check if there was a request by the user for the lift to go to L2 after the robot has entered the lift, or did the lift request to L2 come out of nowhere? Mainly curious about where these LiftRequests came from.

That would be the request by the AGV to move to L2 from L1 after it has moved in. No manual intervention was done in this test.

Edit: Apparently, there are also lift requests to L2 later. So I have no idea, where this comes from...

Edit2: I think it as follows:

The AGV has entered the lift and requested it to go to L2. The lift starts to move, but the status requests still return L1 as current level (L2 is only returned when it reached L2). That is why RMF still sends these L1 requests. The L2 requests starting in line 1126 only appear when the lift arrived at L2 (which is also what /lift_states says at that timestamp).

Test 5: What are the logs on RMF fleet adapter when the lift is ready and doors opened on L1 for the robot to move in?

I didn't save the output, so I will test it again and see. I think it looks like I posted in my previous comment, but I'll check.

xiyuoh commented 1 month ago

Thanks for clarifying! I just spent some time tracing the logs, and the requests provided seem very incoherent. I've mapped them out in the chart below.

image

Commands with white text will be ignored as RMF takes into account the request time and ensures that it was not a past request.

To explain a little about how these lift requests work, the various fleet adapters will publish their lift requests via /adapter_lift_requests to the lift supervisor. The lift supervisor will then process these requests one robot at a time, i.e. only entertain requests from one session id (which usually represents the robot in the fleet_name/robot_name convention) on a first-come-first-serve basis. These filtered requests for the single robot will then be published to the lift adapter on the /lift_requests topic.

You can see from the image that there are some rogue requests being sent on /lift_requests topic that did not come from /adapter_lift_requests. Even though Test 4 seems to behave as it should, I think resolving why this happened may help us with finding out why Test 5 failed and any hidden bugs in our lift request implementation.

To further isolate the issue, I suggest running the same tests after doing the following:

Let me know if you're still facing the same problem after these steps. In the meantime I will try to reproduce this in simulation.

xiyuoh commented 4 weeks ago

I thought more about Test 5 and I noticed that after a request is published on /lift_requests with the session ID neo/neo_1, the session ID published on /lift_states never got updated. That is probably why the robot didn't move in; the session ID did not match the robot name so RMF thinks that the lift was busy with another session. Could you check that your lift adapter is publishing the lift states and populating the session id?

Vortex-TH commented 4 weeks ago

Yesterday, I repeated the following tests (and got some confusing results):

Test 4.1: Idle lift in L2, then request by AGV from L1 --- [**/lift_states**](https://gist.github.com/Vortex-TH/d4e267c91dd264ec0a9c104d3d344cac) [**/lift_requests**](https://gist.github.com/Vortex-TH/c9dbff8030ba3fd99a5d7a85b9068ac0) [**/adapter_lift_requests**](https://gist.github.com/Vortex-TH/43d305e27a99e6f8d1a5803e4b6d20fb) [**Liftadapter output**](https://gist.github.com/Vortex-TH/257890ca7803e03a6e032c9133d739e7) [**RMF nodes output**](https://gist.github.com/Vortex-TH/5d9a1c25cf295ae5f4a1d91e6b05dbf8) **Observation** The lift moves from L2 to L1. The AGV moves in front of the lift, but then nothing happens, although the lift is ready for it to move in. ---
Test 4.2: Idle lift in L2, then request by AGV from L1 --- [**/lift_states**](https://gist.github.com/Vortex-TH/fd84a805ceb187f156eda084268d3e24) [**/lift_requests**](https://gist.github.com/Vortex-TH/35d0b7de27f97a458aae4dfb8f645813) [**/adapter_lift_requests**](https://gist.github.com/Vortex-TH/7a9113ff71d04b239d5b0826a6c65eb5) [**Liftadapter output**](https://gist.github.com/Vortex-TH/49a1fb795a649cf316b1b7ec8b5d2d4c) [**RMF nodes output**](https://gist.github.com/Vortex-TH/eabfdc11858aecd18a7d26cee284e6ae) **Observation** The lift moves from L2 to L1, the AGV moves in to the lift, which then moves to L2. ---
Test 4.3: Idle lift in L2, then request by AGV from L1 (with disabled lift_panel node) --- [**/lift_states**](https://gist.github.com/Vortex-TH/8dc3e73d4feb504d1beb334085fbd0ca) [**/lift_requests**](https://gist.github.com/Vortex-TH/b05c67916c9297a307969a43e1ca8e29) [**/adapter_lift_requests**](https://gist.github.com/Vortex-TH/b4d5fa33e4ebf93027d26211cfe577ac) [**Liftadapter output**](https://gist.github.com/Vortex-TH/e915e0b8f6367910c08c90687f615c5b) [**RMF nodes output**](https://gist.github.com/Vortex-TH/82bc959b12820a4ef60d7cb8f4518a27) **Observation** The lift moves from L2 to L1, the AGV moves in to the lift, which then moves to L2. ---
Test 5.1: Idle lift in L1, then request by AGV from L1 (with disabled lift_panel node) --- [**/lift_states**](https://gist.github.com/Vortex-TH/1cd39c091c2a2fa0b4a4412642a948d8) [**/lift_requests**](https://gist.github.com/Vortex-TH/d0a32907ef31d81b648ba52794370a73) **/adapter_lift_requests** ``` ros2 topic echo /adapter_lift_requests lift_name: MyLift request_time: sec: 1724079769 nanosec: 340637391 session_id: neo/neo_1 request_type: 1 destination_floor: L1 door_state: 2 --- ``` [**Liftadapter output**](https://gist.github.com/Vortex-TH/361d341abb0e21b22f1fa961ff445e98) [**RMF nodes output**](https://gist.github.com/Vortex-TH/440c9a4e7ff2c77e116062a36517588c) **Observation** The AGV moves in front of the lift, but then nothing happens, although the lift is ready for it to move in. ---

I also had a look at the pub/sub nodes of the topics. I noticed that there is an additional publisher (lift_panel_session_node) for the request topic, which is why I disabled the node (and Rviz visualization) in Test 4.3 and 5.1. But I definitely didn't manually send any lift requests from the panel in Test 4!

ros2 topic info /lift_requests -v ``` Type: rmf_lift_msgs/msg/LiftRequest Publisher count: 2 Node name: lift_panel_session_node Node namespace: / Topic type: rmf_lift_msgs/msg/LiftRequest Topic type hash: RIHS01_e8f1e0aa4d172703d0d7840c1876448c6c5d75ab58955faf7de7dddc17c096ac Endpoint type: PUBLISHER GID: 01.10.3e.6f.f4.cd.8a.b1.d5.42.ce.1d.00.00.61.03 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (100) Durability: TRANSIENT_LOCAL Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Node name: rmf_lift_supervisor Node namespace: / Topic type: rmf_lift_msgs/msg/LiftRequest Topic type hash: RIHS01_e8f1e0aa4d172703d0d7840c1876448c6c5d75ab58955faf7de7dddc17c096ac Endpoint type: PUBLISHER GID: 01.10.f5.c6.89.9c.91.df.1f.d3.0c.80.00.00.17.03 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (100) Durability: TRANSIENT_LOCAL Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Subscription count: 2 Node name: _ros2cli_12682 Node namespace: / Topic type: rmf_lift_msgs/msg/LiftRequest Topic type hash: RIHS01_e8f1e0aa4d172703d0d7840c1876448c6c5d75ab58955faf7de7dddc17c096ac Endpoint type: SUBSCRIPTION GID: 01.10.e9.2d.fa.23.77.71.6d.96.7e.64.00.00.0a.04 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (5) Durability: TRANSIENT_LOCAL Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Node name: lift_adapter_template Node namespace: / Topic type: rmf_lift_msgs/msg/LiftRequest Topic type hash: RIHS01_e8f1e0aa4d172703d0d7840c1876448c6c5d75ab58955faf7de7dddc17c096ac Endpoint type: SUBSCRIPTION GID: 01.10.ef.ef.b5.f8.b3.1c.80.29.04.1e.00.00.17.04 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (1) Durability: VOLATILE Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite ```
ros2 topic info /lift_states -v ``` Type: rmf_lift_msgs/msg/LiftState Publisher count: 1 Node name: lift_adapter_template Node namespace: / Topic type: rmf_lift_msgs/msg/LiftState Topic type hash: RIHS01_ce0553cd08eeeb321bdae554efdb6d2ebb2be9755df2e34895cbef55b51f4c06 Endpoint type: PUBLISHER GID: 01.10.ef.ef.b5.f8.b3.1c.80.29.04.1e.00.00.16.03 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (1) Durability: VOLATILE Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Subscription count: 5 Node name: building_systems_visualizer Node namespace: / Topic type: rmf_lift_msgs/msg/LiftState Topic type hash: RIHS01_ce0553cd08eeeb321bdae554efdb6d2ebb2be9755df2e34895cbef55b51f4c06 Endpoint type: SUBSCRIPTION GID: 01.10.2c.d5.a8.27.c5.e0.cc.f6.c2.4a.00.00.19.04 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (1) Durability: VOLATILE Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Node name: lift_panel_session_node Node namespace: / Topic type: rmf_lift_msgs/msg/LiftState Topic type hash: RIHS01_ce0553cd08eeeb321bdae554efdb6d2ebb2be9755df2e34895cbef55b51f4c06 Endpoint type: SUBSCRIPTION GID: 01.10.3e.6f.f4.cd.8a.b1.d5.42.ce.1d.00.00.60.04 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (10) Durability: VOLATILE Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Node name: neo_fleet_adapter Node namespace: / Topic type: rmf_lift_msgs/msg/LiftState Topic type hash: RIHS01_ce0553cd08eeeb321bdae554efdb6d2ebb2be9755df2e34895cbef55b51f4c06 Endpoint type: SUBSCRIPTION GID: 01.10.a5.98.28.41.14.88.85.b6.93.c2.00.00.1a.04 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (100) Durability: VOLATILE Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Node name: _ros2cli_12728 Node namespace: / Topic type: rmf_lift_msgs/msg/LiftState Topic type hash: RIHS01_ce0553cd08eeeb321bdae554efdb6d2ebb2be9755df2e34895cbef55b51f4c06 Endpoint type: SUBSCRIPTION GID: 01.10.c3.f0.5a.38.01.6e.be.16.cc.1b.00.00.0a.04 QoS profile: Reliability: BEST_EFFORT History (Depth): KEEP_LAST (5) Durability: VOLATILE Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Node name: rmf_lift_supervisor Node namespace: / Topic type: rmf_lift_msgs/msg/LiftState Topic type hash: RIHS01_ce0553cd08eeeb321bdae554efdb6d2ebb2be9755df2e34895cbef55b51f4c06 Endpoint type: SUBSCRIPTION GID: 01.10.f5.c6.89.9c.91.df.1f.d3.0c.80.00.00.19.04 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (1) Durability: VOLATILE Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite ```

Results

Now Test 4.1 failed, but 4.2 worked with the same setup, for some reason. 4.3 worked and 5.1 didn't.

I always restarted RMF and lift adapter nodes before all tests (which I also did previously) and the packages are up to date (iron).


I thought more about Test 5 and I noticed that after a request is published on /lift_requests with the session ID neo/neo_1, the session ID published on /lift_states never got updated. That is probably why the robot didn't move in; the session ID did not match the robot name so RMF thinks that the lift was busy with another session. Could you check that your lift adapter is publishing the lift states and populating the session id?

Ok, I guess that means I'll modify lift_adapter_template.py and do some more print debugging. I'll do that with the next test.

xiyuoh commented 4 weeks ago

Unfortunately I haven't been able to reproduce this in simulation with 22.04 + RMF Iron binaries. Some observations about your latest tests:

I'm really interested to understand where these stray END_SESSION requests are coming from so that we can fix existing bugs. I'd need your help gathering a little more info:

  1. You mentioned that the packages are up to date, can I check what is the output when you do a apt list --installed | grep iron-rmf? For reference when I do that, the packages are dated 20240713.
  2. Can I also ask for an output of ros2 topic info /adapter_lift_requests -v?
  3. To ensure that we're capturing all the info we can get, do you think you can do a screen recording like those in this ticket? It'd be helpful to see:
    • ros2 topic echo /lift_requests
    • ros2 topic echo /adapter_lift_requests
    • ros2 topic echo /lift_states
    • The terminal you use to launch the fleet adapter
  4. I should have asked this earlier, but may I know what type of setup are you testing with? I saw that you tried this on real hardware - does that mean real robots + real lift, or real robots + simulated lift? Are you using docker for RMF?
Vortex-TH commented 4 weeks ago

I just realized that the sourced rmf was some compiled version from an earlier test instead of the binary.

Sorry about that. I will repeat the test and make sure it's the correct version. I should have noticed this earlier...

Vortex-TH commented 4 weeks ago

Ok, first the requested data:

apt list --installed | grep iron-rmf ``` ros-iron-rmf-api-msgs/jammy,now 0.1.2-1jammy.20240713.181510 amd64 [installed,automatic] ros-iron-rmf-battery/jammy,now 0.2.1-1jammy.20240711.223637 amd64 [installed,automatic] ros-iron-rmf-building-map-msgs/jammy,now 1.3.1-1jammy.20240711.233958 amd64 [installed,automatic] ros-iron-rmf-building-map-tools/jammy,now 1.7.2-1jammy.20240713.181700 amd64 [installed,automatic] ros-iron-rmf-building-sim-common/jammy,now 2.1.2-1jammy.20240713.181906 amd64 [installed,automatic] ros-iron-rmf-building-sim-gz-classic-plugins/jammy,now 2.1.2-1jammy.20240713.182226 amd64 [installed,automatic] ros-iron-rmf-building-sim-gz-plugins/jammy,now 2.1.2-1jammy.20240713.182226 amd64 [installed,automatic] ros-iron-rmf-charger-msgs/jammy,now 3.1.3-1jammy.20240713.181517 amd64 [installed,automatic] ros-iron-rmf-dev/jammy,now 0.0.1-1jammy.20240731.202307 amd64 [installed] ros-iron-rmf-dispenser-msgs/jammy,now 3.1.3-1jammy.20240713.181645 amd64 [installed,automatic] ros-iron-rmf-door-msgs/jammy,now 3.1.3-1jammy.20240713.181513 amd64 [installed,automatic] ros-iron-rmf-fleet-adapter-python/jammy,now 2.2.6-1jammy.20240713.191142 amd64 [installed,automatic] ros-iron-rmf-fleet-adapter/jammy,now 2.2.6-1jammy.20240713.184205 amd64 [installed,automatic] ros-iron-rmf-fleet-msgs/jammy,now 3.1.3-1jammy.20240713.181539 amd64 [installed,automatic] ros-iron-rmf-ingestor-msgs/jammy,now 3.1.3-1jammy.20240713.182215 amd64 [installed,automatic] ros-iron-rmf-lift-msgs/jammy,now 3.1.3-1jammy.20240713.181641 amd64 [installed,automatic] ros-iron-rmf-obstacle-msgs/jammy,now 3.1.3-1jammy.20240713.181528 amd64 [installed,automatic] ros-iron-rmf-robot-sim-common/jammy,now 2.1.2-1jammy.20240731.185003 amd64 [installed,automatic] ros-iron-rmf-robot-sim-gz-classic-plugins/jammy,now 2.1.2-1jammy.20240731.192754 amd64 [installed,automatic] ros-iron-rmf-robot-sim-gz-plugins/jammy,now 2.1.2-1jammy.20240731.192800 amd64 [installed,automatic] ros-iron-rmf-scheduler-msgs/jammy,now 3.1.3-1jammy.20240713.181536 amd64 [installed,automatic] ros-iron-rmf-site-map-msgs/jammy,now 3.1.3-1jammy.20240713.181526 amd64 [installed,automatic] ros-iron-rmf-task-msgs/jammy,now 3.1.3-1jammy.20240713.182453 amd64 [installed,automatic] ros-iron-rmf-task-ros2/jammy,now 2.2.6-1jammy.20240713.183707 amd64 [installed,automatic] ros-iron-rmf-task-sequence/jammy,now 2.2.5-1jammy.20240713.181650 amd64 [installed,automatic] ros-iron-rmf-task/jammy,now 2.2.5-1jammy.20240711.223755 amd64 [installed,automatic] ros-iron-rmf-traffic-editor-assets/jammy,now 1.7.2-1jammy.20240711.215742 amd64 [installed,automatic] ros-iron-rmf-traffic-editor-test-maps/jammy,now 1.7.2-1jammy.20240713.181844 amd64 [installed,automatic] ros-iron-rmf-traffic-editor/jammy,now 1.7.2-1jammy.20240711.225642 amd64 [installed,automatic] ros-iron-rmf-traffic-examples/jammy,now 3.1.2-1jammy.20240711.223701 amd64 [installed,automatic] ros-iron-rmf-traffic-msgs/jammy,now 3.1.3-1jammy.20240713.181543 amd64 [installed,automatic] ros-iron-rmf-traffic-ros2/jammy,now 2.2.6-1jammy.20240713.182409 amd64 [installed,automatic] ros-iron-rmf-traffic/jammy,now 3.1.2-1jammy.20240711.221356 amd64 [installed,automatic] ros-iron-rmf-utils/jammy,now 1.5.1-1jammy.20240711.221314 amd64 [installed,automatic] ros-iron-rmf-visualization-building-systems/jammy,now 2.1.2-1jammy.20240713.181907 amd64 [installed,automatic] ros-iron-rmf-visualization-fleet-states/jammy,now 2.1.2-1jammy.20240713.182014 amd64 [installed,automatic] ros-iron-rmf-visualization-floorplans/jammy,now 2.1.2-1jammy.20240712.003540 amd64 [installed,automatic] ros-iron-rmf-visualization-msgs/jammy,now 1.3.1-1jammy.20240711.232701 amd64 [installed,automatic] ros-iron-rmf-visualization-navgraphs/jammy,now 2.1.2-1jammy.20240713.183707 amd64 [installed,automatic] ros-iron-rmf-visualization-obstacles/jammy,now 2.1.2-1jammy.20240713.181839 amd64 [installed,automatic] ros-iron-rmf-visualization-rviz2-plugins/jammy,now 2.1.2-1jammy.20240731.201438 amd64 [installed,automatic] ros-iron-rmf-visualization-schedule/jammy,now 2.1.2-1jammy.20240713.183706 amd64 [installed,automatic] ros-iron-rmf-visualization/jammy,now 2.1.2-1jammy.20240731.202219 amd64 [installed,automatic] ros-iron-rmf-websocket/jammy,now 2.2.6-1jammy.20240713.181547 amd64 [installed,automatic] ros-iron-rmf-workcell-msgs/jammy,now 3.1.3-1jammy.20240713.181549 amd64 [installed,automatic] ```
ros2 topic info /adapter_lift_requests -v ``` Type: rmf_lift_msgs/msg/LiftRequest Publisher count: 2 Node name: lift_panel_session_node Node namespace: / Topic type: rmf_lift_msgs/msg/LiftRequest Topic type hash: RIHS01_e8f1e0aa4d172703d0d7840c1876448c6c5d75ab58955faf7de7dddc17c096ac Endpoint type: PUBLISHER GID: 01.10.01.f2.cc.dc.a9.8e.36.ed.9d.c9.00.00.62.03 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (100) Durability: TRANSIENT_LOCAL Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Node name: neo_fleet_adapter Node namespace: / Topic type: rmf_lift_msgs/msg/LiftRequest Topic type hash: RIHS01_e8f1e0aa4d172703d0d7840c1876448c6c5d75ab58955faf7de7dddc17c096ac Endpoint type: PUBLISHER GID: 01.10.2a.fc.99.02.94.f9.88.98.97.19.00.00.1b.03 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (100) Durability: TRANSIENT_LOCAL Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite Subscription count: 1 Node name: rmf_lift_supervisor Node namespace: / Topic type: rmf_lift_msgs/msg/LiftRequest Topic type hash: RIHS01_e8f1e0aa4d172703d0d7840c1876448c6c5d75ab58955faf7de7dddc17c096ac Endpoint type: SUBSCRIPTION GID: 01.10.d6.3c.bb.c0.b5.47.77.f4.7b.74.00.00.18.04 QoS profile: Reliability: RELIABLE History (Depth): KEEP_LAST (100) Durability: TRANSIENT_LOCAL Lifespan: Infinite Deadline: Infinite Liveliness: AUTOMATIC Liveliness lease duration: Infinite ```

Robots and lift are real hardware and I'm not using RMF in docker. I now also made sure I'm using the binary installation of RMF, but Test 4.4 and 5.2 still failed with the same problem (robot doesn't move into the lift).

Test 4.4: Idle lift in L2, then request by AGV from L1 [test4-4.webm](https://github.com/user-attachments/assets/3baa66b7-77cf-4ff2-9f28-6e3ecf0f5970)
Test 4.5: Idle lift in L2, then request by AGV from L1 (repeated Test 4.4) [test4-5.webm](https://github.com/user-attachments/assets/f232e134-abf7-46d5-8036-7101a19b1db2)
Test 5.2: Idle lift in L1, then request by AGV from L1 [test5-2.webm](https://github.com/user-attachments/assets/0322a036-50af-490f-87a1-6f823807963e)
xiyuoh commented 4 weeks ago

Thank you for providing the requested data! I see that the random END_SESSION requests are gone now, that a good sign!

For the remaining issue of why your robot does not enter the lift even when it reached L1 with doors open, I believe it all comes down to a mismatch in session ID. It would help to understand if you made any edits to the lift adapter template (assuming you are using this) for us to figure out how to correct this behavior.

Test 4.4 I can see why the robot does not enter the lift. Once the lift reached L1, the session ID changed from neo/neo_1 to "" (at the 1:26 mark of the video), even though there were no END_SESSION requests from the lift request topics. I suggest checking the lift adapter implementation and ensuring that the lift's session ID is not modified unless the lift adapter receives an END_SESSION request. Specifically you might want to check if this logic is untouched in your lift adapter.

Test 4.5 Same problem as above, but it worked because there was one single message published on /lift_states where the lift is at L1 and the session ID was still neo/neo_1, and therefore RMF allowed the robot to move into the lift. Immediately after that, the session ID becomes "" again. For reference these happened at the 1:24 mark.

Test 5.2 This would be a repeat of the previous issue where the session ID was never updated on MyLift. We can see on /lift_states that the session ID stay "" throughout the video.

Vortex-TH commented 3 weeks ago

I am using this version of lift_adapter_template without any changes to lift_adapter_template.py.

Vortex-TH commented 3 weeks ago

I added some quick print debugging around that adapter logic:

        print()
        print("lift_request:")
        print(self.lift_request)

        if self.lift_request is not None:
            print("Lift request is not None")
            print("and session_id is", self.lift_request.session_id)
            if self.lift_request.request_type == \
                    LiftRequest.REQUEST_END_SESSION:
                print("Lift request is REQUEST_END_SESSION")
                new_state.session_id = ''
            else:
                print("Lift request is not REQUEST_END_SESSION, setting new_state.session_id")
                new_state.session_id = self.lift_request.session_id
        print("Returning new_state:")
        print(new_state)
        print()
        return new_state
lift_request:
rmf_lift_msgs.msg.LiftRequest(lift_name='MyLift', request_time=builtin_interfaces.msg.Time(sec=1724330294, nanosec=333707105), session_id='neo/neo_1', request_type=1, destination_floor='L1', door_state=2)
Lift request is not None
and session_id is neo/neo_1
Lift request is not REQUEST_END_SESSION, setting new_state.session_id
Returning new_state:
rmf_lift_msgs.msg.LiftState(lift_time=builtin_interfaces.msg.Time(sec=1724330295, nanosec=636705808), lift_name='MyLift', available_floors=['L1', 'L2', 'L3'], current_floor='L1', destination_floor='L1', door_state=<DoorState.OPEN: 2>, motion_state=<MotionState.STOPPED: 0>, available_modes=[1, 2], current_mode=2, session_id='neo/neo_1')

lift_request:
None
Returning new_state:
rmf_lift_msgs.msg.LiftState(lift_time=builtin_interfaces.msg.Time(sec=1724330296, nanosec=136698010), lift_name='MyLift', available_floors=['L1', 'L2', 'L3'], current_floor='L1', destination_floor='L1', door_state=<DoorState.OPEN: 2>, motion_state=<MotionState.STOPPED: 0>, available_modes=[1, 2], current_mode=2, session_id='')

[INFO] [1724330296.347279582] [lift_adapter_template]: Requested lift to L1.

lift_request:
rmf_lift_msgs.msg.LiftRequest(lift_name='MyLift', request_time=builtin_interfaces.msg.Time(sec=1724330295, nanosec=332564131), session_id='neo/neo_1', request_type=1, destination_floor='L1', door_state=2)
Lift request is not None
and session_id is neo/neo_1
Lift request is not REQUEST_END_SESSION, setting new_state.session_id
Returning new_state:
rmf_lift_msgs.msg.LiftState(lift_time=builtin_interfaces.msg.Time(sec=1724330296, nanosec=636611981), lift_name='MyLift', available_floors=['L1', 'L2', 'L3'], current_floor='L1', destination_floor='L1', door_state=<DoorState.OPEN: 2>, motion_state=<MotionState.STOPPED: 0>, available_modes=[1, 2], current_mode=2, session_id='neo/neo_1')

It looks like it receives some callbacks with NoneType objects where it sets the session_id to ''

xiyuoh commented 3 weeks ago

Ah I see what's going on, I suspect it is due to the logic inside the lift adapter template. I've made some changes to the template code here on the xiyu/reset_request branch, do you mind applying these changes and let me know if you're still experiencing the same issue?

Vortex-TH commented 3 weeks ago

Sure, but I won't be able to test it until sometime next week.

Vortex-TH commented 3 weeks ago

I tested your latest version and it looks like the robot is now always moving into the lift in all tests, but then the lift does not start moving.

test5-3.webm

xiyuoh commented 3 weeks ago

Glad to know that the robot moves into the lift now.

I see that on /lift_states the destination_floor is not being updated, similar to the previous issue where your session_id wasn't updated correctly. Could you check your lift implementation and ensure that the destination_floor is updating as it should (according to the valid lift requests with the correct session ID)? I believe the issue is that your lift is not properly receiving the lift request to L2, and therefore it isn't moving + its destination_floor is not updated.

xiyuoh commented 3 weeks ago

@Vortex-TH I wanted to add that the PR was just updated today after a round of review, do ensure that your code is updated with the latest changes!

Vortex-TH commented 3 weeks ago

I don't quite understand.. The destination floor should be updated after the lift received the command_lift(L2) call, right? But the lift adapter (LiftAPI) never receives that function call (because it's busy with another request as seen in the video?).

@Vortex-TH I wanted to add that the https://github.com/open-rmf/lift_adapter_template/pull/4 was just updated today after a round of review, do ensure that your code is updated with the latest changes!

Yes, I'm using the version from today

xiyuoh commented 3 weeks ago

@Vortex-TH Thanks for pointing that out! I just updated the PR, I believe the lift adapter was rejecting all new requests as long as it is in the middle of a lift session. I've added a condition to only reject lift requests with different session IDs, will have to trouble you to try the latest code out.

Vortex-TH commented 3 weeks ago

It seems to be working now! Thanks for your help :)

xiyuoh commented 3 weeks ago

That's awesome, thanks for testing it! If there's nothing else I'll close this ticket, feel free to open a new one if you face a different issue.