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.

Sign up for GitHub

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

Jump to bottom

[multi-host] failed to initialize rosout publisher: unable to create zenoh publisher cache #238

Closed
berndpfrommer opened this issue Jul 4, 2024 · 9 comments
Closed

[multi-host] failed to initialize rosout publisher: unable to create zenoh publisher cache #238

berndpfrommer opened this issue Jul 4, 2024 · 9 comments
Labels
bug Something isn't working

Comments

@berndpfrommer
Copy link
Contributor

Scenario is as follows. Two machines, connected to the same wifi router. I'm running a zenohd on one host, and want to query the zenohd from the other host.

Both running the latest version of rmw_zenoh_cpp (Wed Jul 3rd, commit is 747a72e).

Host A [192.168.17.155] < --- wifi -- > Host B [ 192.168.17.249] (runs zenoh_hd)

On Host A, running ros2 topic list fails:

ZENOH_SESSION_CONFIG_URI=${HOME}/.config/rmw_zenoh_session_config.json5 ros2 topic list
[INFO] [1720111205.046398983] [rmw_zenoh_cpp]: Successfully connected to a Zenoh router with id c3505398a7e2fc5f5d6f4d64204756.
[ERROR] [1720111206.056194866] [rmw_zenoh_cpp]: create publisher liveliness: 1
failed to initialize rosout publisher: unable to create zenoh publisher cache, at /opt/ros/src/rolling/src/rmw_zenoh/rmw_zenoh_cpp/src/rmw_zenoh.cpp:633, at ./src/rcl/publisher.c:117

The rmw_zenoh_session_config.json5 file on Host A has this content:

{
  connect: {
    endpoints: [
      "tcp/192.168.17.249:7447",
    ],
  },
}

The debug messages on Host B indicate that the connection is made successfully, but then a read error occurs:

2024-07-04T16:46:50.515086Z DEBUG  rx-0 ThreadId(06) zenoh_transport::unicast::universal::link: RX task failed: Read error on TCP link [::ffff:192.168.17.249]:7447 => [::ffff:192.168.17.155]:60024: early eof at /home/pfrommer/.cargo/git/checkouts/zenoh-cc237f2570fab813/93f93d2/io/zenoh-links/zenoh-link-tcp/src/unicast.rs:130.
2024-07-04T16:46:50.515166Z DEBUG net-0 ThreadId(03) zenoh_transport::unicast::universal::transport: [cde320992ffe7790db9c0d9ea63f3029] Closing transport with peer: 4f3c8070ef6f52be764a440643a6b6f3
2024-07-04T16:46:50.515200Z DEBUG net-0 ThreadId(03) zenoh::net::routing::dispatcher::tables: Close Face{3, 4f3c8070ef6f52be764a440643a6b6f3}

Any advice on how to debug this?

(I also tried starting zenohds on both hosts. They see each other, but any querying (ros2 topic/node list etc fails once the two daemons are talking to each other. I figured the scenario above is the simplest setup to trouble shoot.)
@Yadunund
Copy link
Member

Yadunund commented Jul 4, 2024 •
edited
Loading

Hi @berndpfrommer,

Thanks for the ticket. I can reproduce the issue with two routers running on separate hosts.

@JEnoch any idea if something changed in zenoh-c? This feels like a regression

Edit: If you don't want to run the router Host A, I think you'll need to remove the endpoint specified here so that the inter-host communication between peers is not router via the zenohd router.

@Yadunund
Copy link
Member

Yadunund commented Jul 4, 2024

Please ignore the [ERROR] [1720111206.056194866] [rmw_zenoh_cpp]: create publisher liveliness: 1 printouts. This should have been removed before merging a previous PR and i've opened #239 to clean that up.

@Yadunund Yadunund added the bug Something isn't working label Jul 4, 2024
@Yadunund Yadunund changed the title failed to initialize rosout publisher: unable to create zenoh publisher cache [multi-host] failed to initialize rosout publisher: unable to create zenoh publisher cache Jul 4, 2024
@JEnoch
Copy link
Contributor

JEnoch commented Jul 5, 2024

Weird... I can't reproduce the issue ! Neither with peer-to-peer nor router-to-router configs.
I'm well using 747a72e on both hosts.

Could please you reproduce running ros2 on Host A with RUST_LOG=debug ?

@berndpfrommer
Copy link
Contributor Author

There is this one line in the debug log on Host A that looks suspect:

2024-07-05T15:43:07.378592Z ERROR ThreadId(02) zenohc::publication_cache: Failed requirement for PublicationCache on 0/rosout/rcl_interfaces::msg::dds_::Log_/RIHS01_e28ce254ca8abc06abf92773b74602cdbf116ed34fbaf294fb9f81da9f318eac: the Session is not configured with 'add_timestamp=true' at /home/pfrommer/.cargo/git/checkouts/zenoh-cc237f2570fab813/93f93d2/zenoh-ext/src/publication_cache.rs:138.

Interestingly, this line does not show up w/o debug logging, although error messages should make it into the log.

Here the full debug logs:

Log on Host A:

RUST_LOG=debug ZENOH_SESSION_CONFIG_URI=${HOME}/.config/rmw_zenoh_session_config.json5 ros2 topic list
2024-07-05T15:43:05.672778Z DEBUG ThreadId(02) zenoh::session: Config: Config { id: 2711cbebfb70b4fddab93648df798b01, metadata: Null, mode: None, connect: ConnectConfig { timeout_ms: None, endpoints: [tcp/192.168.17.249:7447], exit_on_failure: None, retry: None }, listen: ListenConfig { timeout_ms: None, endpoints: [], exit_on_failure: None, retry: None }, scouting: ScoutingConf { timeout: None, delay: None, multicast: ScoutingMulticastConf { enabled: None, address: None, interface: None, ttl: None, autoconnect: None, listen: None }, gossip: GossipConf { enabled: None, multihop: None, autoconnect: None } }, timestamping: TimestampingConf { enabled: None, drop_future_timestamp: None }, queries_default_timeout: None, routing: RoutingConf { router: RouterRoutingConf { peers_failover_brokering: None }, peer: PeerRoutingConf { mode: None } }, aggregation: AggregationConf { subscribers: [], publishers: [] }, transport: TransportConf { unicast: TransportUnicastConf { accept_timeout: 10000, accept_pending: 100, max_sessions: 1000, max_links: 1, lowlatency: false, qos: QoSUnicastConf { enabled: true }, compression: CompressionUnicastConf { enabled: false } }, multicast: TransportMulticastConf { join_interval: Some(2500), max_sessions: Some(1000), qos: QoSMulticastConf { enabled: false }, compression: CompressionMulticastConf { enabled: false } }, link: TransportLinkConf { protocols: None, tx: LinkTxConf { sequence_number_resolution: U32, lease: 10000, keep_alive: 4, batch_size: 65535, queue: QueueConf { size: QueueSizeConf { control: 1, real_time: 1, interactive_high: 1, interactive_low: 1, data_high: 2, data: 4, data_low: 2, background: 1 }, congestion_control: CongestionControlConf { wait_before_drop: 1000 }, backoff: 100 }, threads: 4 }, rx: LinkRxConf { buffer_size: 65535, max_message_size: 1073741824 }, tls: TLSConf { root_ca_certificate: None, server_private_key: None, server_certificate: None, client_auth: None, client_private_key: None, client_certificate: None, server_name_verification: None, root_ca_certificate_base64: None, server_private_key_base64: None, server_certificate_base64: None, client_private_key_base64: None, client_certificate_base64: None }, unixpipe: UnixPipeConf { file_access_mask: None } }, shared_memory: SharedMemoryConf { enabled: false }, auth: AuthConf { usrpwd: UsrPwdConf { user: None, password: None, dictionary_file: None }, pubkey: PubKeyConf { public_key_pem: None, private_key_pem: None, public_key_file: None, private_key_file: None, key_size: None, known_keys_file: None } } }, adminspace: AdminSpaceConf { enabled: false, permissions: PermissionsConf { read: true, write: false } }, downsampling: [], access_control: AclConfig { enabled: false, default_permission: Deny, rules: None }, plugins_loading: PluginsLoading { enabled: false, search_dirs: None }, plugins: Object {} }
2024-07-05T15:43:05.672835Z DEBUG ThreadId(02) zenoh::net::runtime: Zenoh Rust API v93f93d2d
2024-07-05T15:43:05.672840Z  INFO ThreadId(02) zenoh::net::runtime: Using ZID: 2711cbebfb70b4fddab93648df798b01
2024-07-05T15:43:05.672849Z DEBUG ThreadId(02) zenoh::net::routing::interceptor::access_control: Access control is disabled
2024-07-05T15:43:05.673105Z DEBUG ThreadId(02) zenoh::net::routing::hat::p2p_peer::gossip: [Gossip] Add node (self) 2711cbebfb70b4fddab93648df798b01
2024-07-05T15:43:05.673129Z DEBUG ThreadId(02) zenoh::net::routing::router: New Face{0, 2711cbebfb70b4fddab93648df798b01}
2024-07-05T15:43:05.673188Z DEBUG ThreadId(02) zenoh::net::runtime::orchestrator: Try to add listener: tcp/[::]:0: ConnectionRetryConf { exit_on_failure: true, period_init_ms: 1000, period_max_ms: 4000, period_increase_factor: 2.0 }
2024-07-05T15:43:05.673316Z DEBUG ThreadId(02) zenoh::net::runtime::orchestrator: Listener added: tcp/[::]:35385
2024-07-05T15:43:05.673530Z  INFO ThreadId(02) zenoh::net::runtime::orchestrator: Zenoh can be reached at: tcp/[fe80::9e6c:2f31:1647:d9a3]:35385
2024-07-05T15:43:05.673540Z  INFO ThreadId(02) zenoh::net::runtime::orchestrator: Zenoh can be reached at: tcp/192.168.17.155:35385
2024-07-05T15:43:05.673548Z DEBUG ThreadId(02) zenoh::net::runtime::orchestrator: Try to connect: tcp/192.168.17.249:7447: global timeout: 18446744073709551615.999999999s, retry: ConnectionRetryConf { exit_on_failure: false, period_init_ms: 1000, period_max_ms: 4000, period_increase_factor: 2.0 }
2024-07-05T15:43:05.673706Z DEBUG ThreadId(02) zenoh::net::runtime::orchestrator: UDP port bound to 224.0.0.224:7446
2024-07-05T15:43:05.673719Z DEBUG ThreadId(02) zenoh::net::runtime::orchestrator: Joined multicast group 224.0.0.224 on interface 192.168.17.155
2024-07-05T15:43:05.673724Z  INFO ThreadId(02) zenoh::net::runtime::orchestrator: zenohd listening scout messages on 224.0.0.224:7446
2024-07-05T15:43:05.673740Z DEBUG ThreadId(02) zenoh::net::runtime::orchestrator: UDP port bound to 192.168.17.155:40202
2024-07-05T15:43:05.673816Z DEBUG net-0 ThreadId(03) zenoh::net::runtime::orchestrator: Waiting for UDP datagram...
2024-07-05T15:43:05.714979Z DEBUG net-0 ThreadId(03) zenoh_transport::unicast::manager: Will use Universal transport!
2024-07-05T15:43:05.715928Z DEBUG net-0 ThreadId(03) zenoh::net::routing::router: New Face{1, c0b94704933104aa5259d65186936bd0}
2024-07-05T15:43:05.715938Z DEBUG net-0 ThreadId(03) zenoh::net::routing::hat::p2p_peer::gossip: [Gossip] Add node (link) c0b94704933104aa5259d65186936bd0
2024-07-05T15:43:05.716046Z DEBUG net-0 ThreadId(03) zenoh_transport::unicast::manager: New transport opened between 2711cbebfb70b4fddab93648df798b01 and c0b94704933104aa5259d65186936bd0 - whatami: router, sn resolution: U32, initial sn: 256125923, qos: true, shm: false, multilink: false, lowlatency: false
2024-07-05T15:43:05.716056Z DEBUG net-0 ThreadId(03) zenoh_transport::unicast::establishment::open: New transport link opened from 2711cbebfb70b4fddab93648df798b01 to c0b94704933104aa5259d65186936bd0: TransportLinkUnicast { link: Link { src: tcp/192.168.17.155:54244, dst: tcp/192.168.17.249:7447, mtu: 65535, is_reliable: true, is_streamed: true }, config: TransportLinkUnicastConfig { direction: Outbound, batch: BatchConfig { mtu: 65535, is_streamed: true, is_compression: false } } }.
2024-07-05T15:43:05.716062Z DEBUG net-0 ThreadId(03) zenoh::net::runtime::orchestrator: Successfully connected to configured peer tcp/192.168.17.249:7447
2024-07-05T15:43:05.893489Z DEBUG acc-0 ThreadId(04) zenoh_link_tcp::unicast: Accepted TCP connection on [::ffff:192.168.17.155]:35385: [::ffff:192.168.17.155]:56120
2024-07-05T15:43:05.893724Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::manager: Will use Universal transport!
2024-07-05T15:43:05.894579Z DEBUG acc-0 ThreadId(04) zenoh::net::routing::router: New Face{2, 7a3dbc5e96a159295c90097f02574f49}
2024-07-05T15:43:05.894595Z DEBUG acc-0 ThreadId(04) zenoh::net::routing::hat::p2p_peer::gossip: [Gossip] Add node (link) 7a3dbc5e96a159295c90097f02574f49
2024-07-05T15:43:05.894633Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::manager: New transport opened between 2711cbebfb70b4fddab93648df798b01 and 7a3dbc5e96a159295c90097f02574f49 - whatami: peer, sn resolution: U32, initial sn: 236144851, qos: true, shm: false, multilink: false, lowlatency: false
2024-07-05T15:43:05.894645Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::establishment::accept: New transport link accepted from 7a3dbc5e96a159295c90097f02574f49 to 2711cbebfb70b4fddab93648df798b01: TransportLinkUnicast { link: Link { src: tcp/[::ffff:192.168.17.155]:35385, dst: tcp/[::ffff:192.168.17.155]:56120, mtu: 65535, is_reliable: true, is_streamed: true }, config: TransportLinkUnicastConfig { direction: Inbound, batch: BatchConfig { mtu: 65535, is_streamed: true, is_compression: false } } }.
[INFO] [1720194186.376691392] [rmw_zenoh_cpp]: Successfully connected to a Zenoh router with id c0b947493314aa5259d65186936bd0.
2024-07-05T15:43:07.377249Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::queries: Route query Face{0, 2711cbebfb70b4fddab93648df798b01}:0 for res @/liveliness/@ros2_lv/0/**
2024-07-05T15:43:07.377317Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::queries: Send final reply Face{0, 2711cbebfb70b4fddab93648df798b01}:0 (no matching queryables or not master)
2024-07-05T15:43:07.378026Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::pubsub: Declare subscription Face{0, 2711cbebfb70b4fddab93648df798b01}
2024-07-05T15:43:07.378041Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::resource: Register resource @/liveliness/@ros2_lv/0/2711cbebfb70b4fddab93648df798b1/0/0/NN/%/%/_ros2cli_858984
2024-07-05T15:43:07.378051Z DEBUG ThreadId(02) zenoh::net::routing::hat::p2p_peer::pubsub: Register subscription @/liveliness/@ros2_lv/0/2711cbebfb70b4fddab93648df798b1/0/0/NN/%/%/_ros2cli_858984 for Face{0, 2711cbebfb70b4fddab93648df798b01}
[ERROR] [1720194187.378558753] [rmw_zenoh_cpp]: create publisher liveliness: 1
2024-07-05T15:43:07.378583Z DEBUG ThreadId(02) zenoh_ext::publication_cache: Create PublicationCache on 0/rosout/rcl_interfaces::msg::dds_::Log_/RIHS01_e28ce254ca8abc06abf92773b74602cdbf116ed34fbaf294fb9f81da9f318eac with history=1000 resource_limit=None
2024-07-05T15:43:07.378592Z ERROR ThreadId(02) zenohc::publication_cache: Failed requirement for PublicationCache on 0/rosout/rcl_interfaces::msg::dds_::Log_/RIHS01_e28ce254ca8abc06abf92773b74602cdbf116ed34fbaf294fb9f81da9f318eac: the Session is not configured with 'add_timestamp=true' at /home/pfrommer/.cargo/git/checkouts/zenoh-cc237f2570fab813/93f93d2/zenoh-ext/src/publication_cache.rs:138.
2024-07-05T15:43:07.378642Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::pubsub: Undeclare subscription Face{0, 2711cbebfb70b4fddab93648df798b01}
2024-07-05T15:43:07.378650Z DEBUG ThreadId(02) zenoh::net::routing::hat::p2p_peer::pubsub: Unregister client subscription @/liveliness/@ros2_lv/0/2711cbebfb70b4fddab93648df798b1/0/0/NN/%/%/_ros2cli_858984 for Face{0, 2711cbebfb70b4fddab93648df798b01}
failed to initialize rosout publisher: unable to create zenoh publisher cache, at /opt/ros/src/rolling/src/rmw_zenoh/rmw_zenoh_cpp/src/rmw_zenoh.cpp:633, at ./src/rcl/publisher.c:117
2024-07-05T15:43:07.400000Z DEBUG ThreadId(02) zenoh_transport::unicast::universal::transport: [2711cbebfb70b4fddab93648df798b01] Closing transport with peer: c0b94704933104aa5259d65186936bd0
2024-07-05T15:43:07.400020Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::tables: Close Face{1, c0b94704933104aa5259d65186936bd0}
2024-07-05T15:43:07.440280Z DEBUG ThreadId(02) zenoh_transport::unicast::universal::transport: [2711cbebfb70b4fddab93648df798b01] Closing transport with peer: 7a3dbc5e96a159295c90097f02574f49
2024-07-05T15:43:07.440309Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::tables: Close Face{2, 7a3dbc5e96a159295c90097f02574f49}
2024-07-05T15:43:07.440889Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::tables: Close Face{0, 2711cbebfb70b4fddab93648df798b01}

Log on Host B:

RUST_LOG=debug ros2 run rmw_zenoh_cpp rmw_zenohd                                                                                                                                                                                                                                                                                                                                                             
2024-07-05T15:42:58.768626Z DEBUG ThreadId(02) zenoh::session: Config: Config { id: c0b94704933104aa5259d65186936bd0, metadata: Null, mode: Some(Router), connect: ConnectConfig { timeout_ms: None, endpoints: [], exit_on_failure: None, retry: None }, listen: ListenConfig { timeout_ms: None, endpoints: [tcp/[::]:7447], exit_on_failure: None, retry: None }, scouting: ScoutingConf { timeout: Some(3000), delay: Some(1), multic
ast: ScoutingMulticastConf { enabled: Some(false), address: Some(224.0.0.224:7446), interface: Some("auto"), ttl: None, autoconnect: Some(Dependent(ModeValues { router: Some(WhatAmIMatcher(128)), peer: Some(WhatAmIMatcher(131)), client: None })), listen: Some(Unique(true)) }, gossip: GossipConf { enabled: Some(true), multihop: Some(false), autoconnect: Some(Dependent(ModeValues { router: Some(WhatAmIMatcher(128)), peer: S
ome(WhatAmIMatcher(131)), client: None })) } }, timestamping: TimestampingConf { enabled: Some(Dependent(ModeValues { router: Some(true), peer: Some(true), client: Some(false) })), drop_future_timestamp: Some(false) }, queries_default_timeout: Some(10000), routing: RoutingConf { router: RouterRoutingConf { peers_failover_brokering: Some(true) }, peer: PeerRoutingConf { mode: Some("peer_to_peer") } }, aggregation: Aggregat
ionConf { subscribers: [], publishers: [] }, transport: TransportConf { unicast: TransportUnicastConf { accept_timeout: 10000, accept_pending: 100, max_sessions: 1000, max_links: 1, lowlatency: false, qos: QoSUnicastConf { enabled: true }, compression: CompressionUnicastConf { enabled: false } }, multicast: TransportMulticastConf { join_interval: Some(2500), max_sessions: Some(1000), qos: QoSMulticastConf { enabled: false }, compression: CompressionMulticastConf { enabled: false } }, link: TransportLinkConf { protocols: None, tx: LinkTxConf { sequence_number_resolution: U32, lease: 10000, keep_alive: 4, batch_size: 65535, queue: QueueConf { size: QueueSizeConf { control: 1, real_time: 1, interactive_high: 1, interactive_low: 1, data_high: 2, data: 4, data_low: 4, background: 4 }, congestion_control: CongestionControlConf { wait_before_drop: 1000 }, backoff: 100 }, threads: 7 }, rx: LinkRxConf { buffer_size: 65535, max_message_size: 1073741824 }, tls: TLSConf { root_ca_certificate: None, server_private_key: None, server_certificate: None, client_auth: Some(false), client_private_key: None, client_certificate: None, server_name_verification: None, root_ca_certificate_base64: None, server_private_key_base64: None, server_certificate_base64: None, client_private_key_base64: None, client_certificate_base64: None }, unixpipe: UnixPipeConf { file_access_mask: None } }, shared_memory: SharedMemoryConf { enabled: false }, auth: AuthConf { usrpwd: UsrPwdConf { user: None, password: None, dictionary_file: None }, pubkey: PubKeyConf { public_key_pem: None, private_key_pem: None, public_key_file: None, private_key_file: None, key_size: None, known_keys_file: None } } }, adminspace: AdminSpaceConf { enabled: false, permissions: PermissionsConf { read: true, write: false } }, downsampling: [], access_control: AclConfig { enabled: false, default_permission: Deny, rules: None }, plugins_loading: PluginsLoading { enabled: false, search_dirs: None }, plugins: Object {} }
2024-07-05T15:42:58.768682Z DEBUG ThreadId(02) zenoh::net::runtime: Zenoh Rust API v93f93d2d                                                                                                                        
2024-07-05T15:42:58.768684Z  INFO ThreadId(02) zenoh::net::runtime: Using ZID: c0b94704933104aa5259d65186936bd0                                                                                                     
2024-07-05T15:42:58.768687Z DEBUG ThreadId(02) zenoh::net::routing::interceptor::access_control: Access control is disabled                                                                                         
2024-07-05T15:42:58.768785Z DEBUG ThreadId(02) zenoh::net::routing::hat::router::network: [Routers network] Add node (self) c0b94704933104aa5259d65186936bd0
2024-07-05T15:42:58.768789Z DEBUG ThreadId(02) zenoh::net::routing::hat::router::network: [Peers network] Add node (self) c0b94704933104aa5259d65186936bd0                                                          
2024-07-05T15:42:58.768794Z DEBUG ThreadId(02) zenoh::net::routing::router: New Face{0, c0b94704933104aa5259d65186936bd0}                                                                                           
2024-07-05T15:42:58.768805Z DEBUG ThreadId(02) zenoh::net::runtime::orchestrator: Try to add listener: tcp/[::]:7447: ConnectionRetryConf { exit_on_failure: true, period_init_ms: 1000, period_max_ms: 4000, period_increase_factor: 2.0 }
2024-07-05T15:42:58.768846Z DEBUG ThreadId(02) zenoh::net::runtime::orchestrator: Listener added: tcp/[::]:7447                                                                                                     
2024-07-05T15:42:58.769028Z  INFO ThreadId(02) zenoh::net::runtime::orchestrator: Zenoh can be reached at: tcp/[fe80::127c:61ff:fe3d:a49d]:7447                                                                     
2024-07-05T15:42:58.769030Z  INFO ThreadId(02) zenoh::net::runtime::orchestrator: Zenoh can be reached at: tcp/[fe80::ca5e:a9ff:fe75:c7cc]:7447                                                                     
2024-07-05T15:42:58.769031Z  INFO ThreadId(02) zenoh::net::runtime::orchestrator: Zenoh can be reached at: tcp/192.168.7.121:7447                                                                                   
2024-07-05T15:42:58.769032Z  INFO ThreadId(02) zenoh::net::runtime::orchestrator: Zenoh can be reached at: tcp/192.168.17.249:7447                                                                                  
Started Zenoh router with id c0b947493314aa5259d65186936bd0.                                              
Enter 'q' to quit...                                                                                      
2024-07-05T15:43:05.624851Z DEBUG acc-0 ThreadId(04) zenoh_link_tcp::unicast: Accepted TCP connection on [::ffff:192.168.17.249]:7447: [::ffff:192.168.17.155]:54244
2024-07-05T15:43:05.631618Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::manager: Will use Universal transport!                                                                                               
2024-07-05T15:43:05.633413Z DEBUG acc-0 ThreadId(04) zenoh::net::routing::router: New Face{1, 2711cbebfb70b4fddab93648df798b01}                                                                                     
2024-07-05T15:43:05.633445Z DEBUG acc-0 ThreadId(04) zenoh::net::routing::hat::router::network: [Peers network] Add node (link) 2711cbebfb70b4fddab93648df798b01
2024-07-05T15:43:05.633855Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::manager: New transport opened between c0b94704933104aa5259d65186936bd0 and 2711cbebfb70b4fddab93648df798b01 - whatami: peer, sn resolution: U32, initial sn: 137662424, qos: true, shm: false, multilink: false, lowlatency: false
2024-07-05T15:43:05.633893Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::establishment::accept: New transport link accepted from 2711cbebfb70b4fddab93648df798b01 to c0b94704933104aa5259d65186936bd0: TransportLinkUnicast { link: Link { src: tcp/[::ffff:192.168.17.249]:7447, dst: tcp/[::ffff:192.168.17.155]:54244, mtu: 65535, is_reliable: true, is_streamed: true }, config: TransportLinkUnicastConfig { direction: Inbound, batch: BatchConfig { mtu: 65535, is_streamed: true, is_compression: false } } }.
2024-07-05T15:43:05.830550Z DEBUG acc-0 ThreadId(04) zenoh_link_tcp::unicast: Accepted TCP connection on [::ffff:192.168.7.121]:7447: [::ffff:192.168.7.140]:40058
2024-07-05T15:43:05.837330Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::manager: Will use Universal transport!                                                                                               
2024-07-05T15:43:05.838874Z DEBUG acc-0 ThreadId(04) zenoh::net::routing::router: New Face{2, 7a3dbc5e96a159295c90097f02574f49}                                                                                     
2024-07-05T15:43:05.838958Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::manager: New transport opened between c0b94704933104aa5259d65186936bd0 and 7a3dbc5e96a159295c90097f02574f49 - whatami: peer, sn resolution: U32, initial sn: 88523565, qos: true, shm: false, multilink: false, lowlatency: false
2024-07-05T15:43:05.838973Z DEBUG acc-0 ThreadId(04) zenoh_transport::unicast::establishment::accept: New transport link accepted from 7a3dbc5e96a159295c90097f02574f49 to c0b94704933104aa5259d65186936bd0: TransportLinkUnicast { link: Link { src: tcp/[::ffff:192.168.7.121]:7447, dst: tcp/[::ffff:192.168.7.140]:40058, mtu: 65535, is_reliable: true, is_streamed: true }, config: TransportLinkUnicastConfig { direction: Inbound, batch: BatchConfig { mtu: 65535, is_streamed: true, is_compression: false } } }.
2024-07-05T15:43:05.842930Z DEBUG acc-0 ThreadId(04) zenoh_link_tcp::unicast: Accepted TCP connection on [::ffff:192.168.17.249]:7447: [::ffff:192.168.17.155]:54256
2024-07-05T15:43:06.957352Z DEBUG acc-0 ThreadId(04) zenoh_link_tcp::unicast: Accepted TCP connection on [::ffff:192.168.17.249]:7447: [::ffff:192.168.17.155]:54266
2024-07-05T15:43:07.358975Z DEBUG  rx-0 ThreadId(06) zenoh::net::routing::dispatcher::resource: Register resource @/liveliness/@ros2_lv/0/2711cbebfb70b4fddab93648df798b1/0/0/NN/%/%/_ros2cli_858984
2024-07-05T15:43:07.359131Z DEBUG  rx-0 ThreadId(06) zenoh::net::routing::dispatcher::pubsub: Declare subscription Face{1, 2711cbebfb70b4fddab93648df798b01}
2024-07-05T15:43:07.359147Z DEBUG  rx-0 ThreadId(06) zenoh::net::routing::hat::router::pubsub: Register subscription @/liveliness/@ros2_lv/0/2711cbebfb70b4fddab93648df798b1/0/0/NN/%/%/_ros2cli_858984 for Face{1, 2711cbebfb70b4fddab93648df798b01}
2024-07-05T15:43:07.359169Z DEBUG  rx-0 ThreadId(06) zenoh::net::routing::hat::router::pubsub: Register router subscription @/liveliness/@ros2_lv/0/2711cbebfb70b4fddab93648df798b1/0/0/NN/%/%/_ros2cli_858984 (router: c0b94704933104aa5259d65186936bd0)
2024-07-05T15:43:07.359184Z DEBUG  rx-0 ThreadId(06) zenoh::net::routing::hat::router: failover_brokering 2711cbebfb70b4fddab93648df798b01 7a3dbc5e96a159295c90097f02574f49 ([c0b94704933104aa5259d65186936bd0, 7a3dbc5e96a159295c90097f02574f49])
2024-07-05T15:43:07.359249Z DEBUG  rx-0 ThreadId(06) zenoh::net::routing::dispatcher::pubsub: Undeclare subscription Face{1, 2711cbebfb70b4fddab93648df798b01}
2024-07-05T15:43:07.359260Z DEBUG  rx-0 ThreadId(06) zenoh::net::routing::hat::router::pubsub: Unregister client subscription @/liveliness/@ros2_lv/0/2711cbebfb70b4fddab93648df798b1/0/0/NN/%/%/_ros2cli_858984 for Face{1, 2711cbebfb70b4fddab93648df798b01}
2024-07-05T15:43:07.359273Z DEBUG  rx-0 ThreadId(06) zenoh::net::routing::hat::router::pubsub: Unregister router subscription @/liveliness/@ros2_lv/0/2711cbebfb70b4fddab93648df798b1/0/0/NN/%/%/_ros2cli_858984 (router: c0b94704933104aa5259d65186936bd0)
2024-07-05T15:43:07.359343Z DEBUG  rx-0 ThreadId(06) zenoh_transport::unicast::universal::link: RX task failed: Read error on TCP link [::ffff:192.168.17.249]:7447 => [::ffff:192.168.17.155]:54244: early eof at /home/pfrommer/.cargo/git/checkouts/zenoh-cc237f2570fab813/93f93d2/io/zenoh-links/zenoh-link-tcp/src/unicast.rs:130.
2024-07-05T15:43:07.359474Z DEBUG net-0 ThreadId(03) zenoh_transport::unicast::universal::transport: [c0b94704933104aa5259d65186936bd0] Closing transport with peer: 2711cbebfb70b4fddab93648df798b01
2024-07-05T15:43:07.359545Z DEBUG net-0 ThreadId(03) zenoh::net::routing::dispatcher::tables: Close Face{1, 2711cbebfb70b4fddab93648df798b01}
2024-07-05T15:43:07.359768Z DEBUG  rx-0 ThreadId(06) zenoh_transport::unicast::universal::transport: [c0b94704933104aa5259d65186936bd0] Closing transport with peer: 2711cbebfb70b4fddab93648df798b01
2024-07-05T15:43:07.525168Z DEBUG  rx-1 ThreadId(07) zenoh::net::routing::dispatcher::resource: Register resource @/liveliness/@ros2_lv/0/7a3dbc5e96a159295c9097f2574f49/0/0/NN/%/%/_ros2cli_daemon_0_a8d3190452814a85b4e9b4ede3a4291d
2024-07-05T15:43:07.525278Z DEBUG  rx-1 ThreadId(07) zenoh::net::routing::dispatcher::pubsub: Declare subscription Face{2, 7a3dbc5e96a159295c90097f02574f49}
2024-07-05T15:43:07.525301Z DEBUG  rx-1 ThreadId(07) zenoh::net::routing::hat::router::pubsub: Register subscription @/liveliness/@ros2_lv/0/7a3dbc5e96a159295c9097f2574f49/0/0/NN/%/%/_ros2cli_daemon_0_a8d3190452814a85b4e9b4ede3a4291d for Face{2, 7a3dbc5e96a159295c90097f02574f49}
2024-07-05T15:43:07.525326Z DEBUG  rx-1 ThreadId(07) zenoh::net::routing::hat::router::pubsub: Register router subscription @/liveliness/@ros2_lv/0/7a3dbc5e96a159295c9097f2574f49/0/0/NN/%/%/_ros2cli_daemon_0_a8d3190452814a85b4e9b4ede3a4291d (router: c0b94704933104aa5259d65186936bd0)
2024-07-05T15:43:07.525390Z DEBUG  rx-1 ThreadId(07) zenoh::net::routing::dispatcher::pubsub: Undeclare subscription Face{2, 7a3dbc5e96a159295c90097f02574f49}
2024-07-05T15:43:07.525409Z DEBUG  rx-1 ThreadId(07) zenoh::net::routing::hat::router::pubsub: Unregister client subscription @/liveliness/@ros2_lv/0/7a3dbc5e96a159295c9097f2574f49/0/0/NN/%/%/_ros2cli_daemon_0_a8d3190452814a85b4e9b4ede3a4291d for Face{2, 7a3dbc5e96a159295c90097f02574f49}
2024-07-05T15:43:07.525431Z DEBUG  rx-1 ThreadId(07) zenoh::net::routing::hat::router::pubsub: Unregister router subscription @/liveliness/@ros2_lv/0/7a3dbc5e96a159295c9097f2574f49/0/0/NN/%/%/_ros2cli_daemon_0_a8d3190452814a85b4e9b4ede3a4291d (router: c0b94704933104aa5259d65186936bd0)
2024-07-05T15:43:08.985217Z DEBUG  rx-0 ThreadId(06) zenoh_transport::unicast::universal::link: RX task failed: Read error on TCP link [::ffff:192.168.7.121]:7447 => [::ffff:192.168.7.140]:40058: early eof at /home/pfrommer/.cargo/git/checkouts/zenoh-cc237f2570fab813/93f93d2/io/zenoh-links/zenoh-link-tcp/src/unicast.rs:130.
2024-07-05T15:43:08.985337Z DEBUG net-0 ThreadId(03) zenoh_transport::unicast::universal::transport: [c0b94704933104aa5259d65186936bd0] Closing transport with peer: 7a3dbc5e96a159295c90097f02574f49
2024-07-05T15:43:08.985378Z DEBUG net-0 ThreadId(03) zenoh::net::routing::dispatcher::tables: Close Face{2, 7a3dbc5e96a159295c90097f02574f49}
2024-07-05T15:43:12.995366Z DEBUG ThreadId(02) zenoh::net::routing::dispatcher::tables: Close Face{0, c0b94704933104aa5259d65186936bd0}

@JEnoch
Copy link
Contributor

JEnoch commented Jul 5, 2024

OK, that makes sense:
You're probably using a custom config for ZENOH_SESSION_CONFIG_URI which was not copied from the default one. Thus it's missing the timestamping.enabled.peer = true setting which makes the Nodes to automatically add timestamps with each publications.

By default Zenoh has this timestamping disabled for the peers, to avoid paying the cost if not required.
But timestamping is required when using the PublicationCache and the QueryingSubscriber, and thus it's also required for rmw_zenoh which use those for TRANSIENT_LOCAL implementation.

@JEnoch
Copy link
Contributor

JEnoch commented Jul 5, 2024

Interestingly, this line does not show up w/o debug logging, although error messages should make it into the log.

That's because the logging library used by Zenoh considers not setting RUST_LOG environment variable is equivalent to RUST_LOG=none. Thus no logging at all.

@clalancette @Yadunund : I think that is RUST_LOG is not defined, we should implicitly set RUST_LOG=warn before each call to z_open() (Node and Router). If you agree I'll do a PR.

@berndpfrommer
Copy link
Contributor Author

Ironically I started out with a full copy of the config file, but then read the cryptic warning on line 3 of said file:

/// Note that the values here are correctly typed, but may not be sensible, so copying this file to change only the parts that matter to you is not good practice.

and the example config here was also bare bones, so I removed the rest of the config.

@clalancette
Copy link
Collaborator

@clalancette @Yadunund : I think that is RUST_LOG is not defined, we should implicitly set RUST_LOG=warn before each call to z_open() (Node and Router). If you agree I'll do a PR.

That seems reasonable to me, at least for now. Please feel free to open a PR and I'm happy to review.

@JEnoch JEnoch mentioned this issue Jul 15, 2024
Merged
@Yadunund
Copy link
Member

Closing as this turned out to be a configuration issue. Please feel free to reopen if this issue surfaces again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@clalancette @JEnoch @berndpfrommer @Yadunund