vsomeip icon indicating copy to clipboard operation
vsomeip copied to clipboard

Published 20 hours ago • verified publisher icon COVESA

[BUG]: In QNX system, subscribe-sample can not receive SUBSCRIBE ACK , can not receive message.

Open Lynn-1997 opened this issue 1 year ago • 6 comments

vSomeip Version

V3.4.10

Boost Version

1.76

Environment

QNX7.1

Describe the bug

Start in this order occur erro: 1、start routingmanagerd, as routing 2、start notify-sample, offer service 3、start subscribe-sample, subscribe service subscribe-sample can not receive SUBSCRIBE ACK , can not receive message.

Start in this order: 1、start notify-sample, as routing and offer service 2、start subscribe-sample, subscribe service subscribe-sample can receive SUBSCRIBE ACK , and can receive message.

Reproduction Steps

#1 Compile V3.4.10 demo based on source code. #2 Execute within QNX system step 1、start routingmanagerd, as routing env VSOMEIP_CONFIGURATION=/mnt/etc/vsomeip.json; VSOMEIP_APPLICATION_NAME=routingmanagerd; ./bin/routingmanagerd>/Log_QNX/vsomeip_log/routingmanagerd.log& 2、start notify-sample, offer service env VSOMEIP_CONFIGURATION=/mnt/etc/vsomeip.json; VSOMEIP_APPLICATION_NAME=notify-sample; ./bin/notify-sample>/Log_QNX/vsomeip_log/notify.log& 3、start subscribe-sample, subscribe service env VSOMEIP_CONFIGURATION=/mnt/etc/vsomeip.json; VSOMEIP_APPLICATION_NAME=subscribe-sample; ./bin/subscribe-sample>/Log_QNX/vsomeip_log/subscribe.log& config: vsomeip.json

Expected behaviour

1、subscribe-sample log include: SUBSCRIBE ACK(6666): [1234.5678.4465.ffff] 2、subscribe-sample log can recieve notify message.

Logs and Screenshots

notify.log routingmanagerd.log subscribe.log

Lynn-1997 avatar Nov 16 '24 10:11 Lynn-1997

I'm not too familiar with this example code, but I see it's registering for SAMPLE_EVENT_ID == 0x8778 which we can see in your log:

1970-01-01 00:06:24.842109 [info] REGISTER EVENT(1277): [1234.5678.8778:eventtype=2:is_provided=true:reliable=255]

however the vsomeip.json that you attached has events 0x0777 ... 0x0779 without the leading 8. I checked the sample config files and the event numbers vary between the local and remote examples. I don't know if this is significant

joeyoravec avatar Dec 05 '24 14:12 joeyoravec

{ "unicast" : "192.168.1.1", "logging": { "level": "debug", "console": "true", "file": { "enable": "true", "path": " /Log_QNX/vsomeip_log/routingmanagerd.log" }, "dlt": "false" }, "applications" : [ { "name" : "notify-sample", "id" : "0x1277" }, { "name" : "subscribe-sample", "id" : "0x1344" }, { "name" : "routingmanagerd", "id" : "0x6666" } ], "services" : [ { "service" : "0x1234", "instance" : "0x5678", "unreliable" : "30509", "events" : [ { "event" : "0x8778", "is_field" : "true", "is_reliable" : "false" } ], "eventgroups" : [ { "eventgroup" : "0x4465", "events" : [ "0x8778" ] } ] } ], "routing" : "routingmanagerd", "service-discovery" : { "enable" : "true", "multicast" : "224.244.224.245", "port" : "30490", "protocol" : "udp", "initial_delay_min" : "10", "initial_delay_max" : "100", "repetitions_base_delay" : "200", "repetitions_max" : "3", "ttl" : "3", "cyclic_offer_delay" : "2000", "request_response_delay" : "1500" } }

Lynn-1997 avatar Dec 12 '24 06:12 Lynn-1997

routingmanagerd log： 1970-01-01 00:00:36.366288 [info] Using configuration file: "/mnt/etc/vsomeip.json". 1970-01-01 00:00:36.366297 [info] Parsed vsomeip configuration in 8ms 1970-01-01 00:00:36.366298 [info] Configuration module loaded. 1970-01-01 00:00:36.366298 [info] Security disabled! 1970-01-01 00:00:36.366298 [info] Initializing vsomeip (3.4.10) application "routingmanagerd". 1970-01-01 00:00:36.366298 [info] Instantiating routing manager [Host]. 1970-01-01 00:00:36.366298 [info] create_routing_root: Routing root @ /var/vsomeip/vsomeip-0 1970-01-01 00:00:36.366307 [info] Service Discovery enabled. Trying to load module. 1970-01-01 00:00:36.366398 [info] Service Discovery module loaded. 1970-01-01 00:00:36.366398 [info] Application(routingmanagerd, 6666) is initialized (11, 100). 1970-01-01 00:00:36.366398 [info] Starting vsomeip application "routingmanagerd" (6666) using 2 threads I/O nice 255 1970-01-01 00:00:36.366398 [info] main dispatch thread id from application: 6666 (routingmanagerd) is: 5 1970-01-01 00:00:36.366398 [info] shutdown thread id from application: 6666 (routingmanagerd) is: 6 1970-01-01 00:00:36.366408 [info] udp_server_endpoint_impl: SO_RCVBUF is: 1703936 (1703936) local port:30490 1970-01-01 00:00:36.366408 [debug] Joining to multicast group 224.244.224.245 from 192.168.1.1 1970-01-01 00:00:36.366408 [info] SOME/IP routing ready. 1970-01-01 00:00:36.366408 [info] udp_server_endpoint_impl: SO_RCVBUF is: 1703936 (1703936) local port:30490 1970-01-01 00:00:36.366408 [info] Watchdog is disabled! 1970-01-01 00:00:36.366408 [info] io thread id from application: 6666 (routingmanagerd) is: 8 1970-01-01 00:00:36.366408 [info] io thread id from application: 6666 (routingmanagerd) is: 1 1970-01-01 00:00:44.444217 [info] rms::on_message: 02 00 00 77 12 02 00 00 00 00 00 1970-01-01 00:00:44.444217 [info] Application/Client 1277 is registering. 1970-01-01 00:00:44.444227 [info] Client [6666] is connecting to [1277] at /var/vsomeip/vsomeip-1277 1970-01-01 00:00:44.444239 [info] rms::on_message: 06 00 00 77 12 00 00 00 00 1970-01-01 00:00:44.444239 [info] REGISTERED_ACK(1277) 1970-01-01 00:00:44.444239 [info] rms::on_message: 10 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:00:44.444239 [info] udp_server_endpoint_impl: SO_RCVBUF is: 1703936 (1703936) local port:30509 1970-01-01 00:00:44.444249 [info] OFFER(1277): [1234.5678:0.0] (true) 1970-01-01 00:00:44.444255 [info] rms::on_message: 1b 00 00 77 12 0e 00 00 00 34 12 78 56 78 87 02 01 ff 00 01 00 65 44 1970-01-01 00:00:44.444255 [info] REGISTER EVENT(1277): [1234.5678.8778:eventtype=2:is_provided=true:reliable=255] 1970-01-01 00:00:54.544308 [info] rms::on_message: 11 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:00:54.544308 [info] STOP OFFER(1277): [1234.5678:0.0] (true) 1970-01-01 00:00:57.578417 [info] rms::on_message: 02 00 00 44 13 02 00 00 00 00 00 1970-01-01 00:00:57.578418 [info] Application/Client 1344 is registering. 1970-01-01 00:00:57.578420 [info] Client [6666] is connecting to [1344] at /var/vsomeip/vsomeip-1344 1970-01-01 00:00:57.578428 [info] rms::on_message: 06 00 00 44 13 00 00 00 00 1970-01-01 00:00:57.578428 [info] REGISTERED_ACK(1344) 1970-01-01 00:00:57.578428 [info] rms::on_message: 1b 00 00 44 13 0e 00 00 00 34 12 78 56 78 87 02 00 ff 00 01 00 65 44 1970-01-01 00:00:57.578438 [info] REGISTER EVENT(1344): [1234.5678.8778:eventtype=2:is_provided=false:reliable=255] 1970-01-01 00:00:57.578532 [info] rms::on_message: 14 00 00 44 13 09 00 00 00 34 12 78 56 ff ff ff ff ff 1970-01-01 00:00:57.578534 [info] REQUEST(1344): [1234.5678:255.4294967295] 1970-01-01 00:00:57.578534 [info] Avoid trigger SD find-service message for local service/instance/major/minor: 1234/5678/255/4294967295

1970-01-01 00:01:04.644423 [info] rms::on_message: 10 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:04.644429 [info] udp_server_endpoint_impl: SO_RCVBUF is: 1703936 (1703936) local port:30509 1970-01-01 00:01:04.644429 [info] OFFER(1277): [1234.5678:0.0] (true)

1970-01-01 00:01:14.744539 [info] rms::on_message: 11 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:14.744539 [info] STOP OFFER(1277): [1234.5678:0.0] (true)

1970-01-01 00:01:24.844696 [info] rms::on_message: 10 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:24.844739 [info] udp_server_endpoint_impl: SO_RCVBUF is: 1703936 (1703936) local port:30509 1970-01-01 00:01:24.844781 [info] OFFER(1277): [1234.5678:0.0] (true) 1970-01-01 00:01:34.944898 [info] rms::on_message: 11 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:34.944958 [info] STOP OFFER(1277): [1234.5678:0.0] (true)

1970-01-01 00:01:44.044991 [info] rms::on_message: 10 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:44.045027 [info] udp_server_endpoint_impl: SO_RCVBUF is: 1703936 (1703936) local port:30509 1970-01-01 00:01:44.045041 [info] OFFER(1277): [1234.5678:0.0] (true) 1970-01-01 00:01:54.145126 [info] rms::on_message: 11 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:54.145146 [info] STOP OFFER(1277): [1234.5678:0.0] (true) 1970-01-01 00:02:04.245240 [info] rms::on_message: 10 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:02:04.245245 [info] udp_server_endpoint_impl: SO_RCVBUF is: 1703936 (1703936) local port:30509 1970-01-01 00:02:04.245245 [info] OFFER(1277): [1234.5678:0.0] (true)

Lynn-1997 avatar Dec 12 '24 06:12 Lynn-1997

notify-sample log: 1970-01-01 00:00:44.444185 [info] Using configuration file: "/mnt/etc/vsomeip.json". 1970-01-01 00:00:44.444187 [info] Parsed vsomeip configuration in 7ms 1970-01-01 00:00:44.444187 [info] Configuration module loaded. 1970-01-01 00:00:44.444187 [info] Security disabled! 1970-01-01 00:00:44.444187 [info] Initializing vsomeip (3.4.10) application "notify-sample". 1970-01-01 00:00:44.444187 [info] Instantiating routing manager [Proxy]. 1970-01-01 00:00:44.444187 [info] Client [1277] is connecting to [0] at /var/vsomeip/vsomeip-0 1970-01-01 00:00:44.444187 [info] Application(notify-sample, 1277) is initialized (11, 100). 1970-01-01 00:00:44.444187 [info] offer_event: Event [1234.5678.8778] uses configured cycle time 0ms 1970-01-01 00:00:44.444187 [info] Starting vsomeip application "notify-sample" (1277) using 2 threads I/O nice 255 Setting event (Length=1). 1970-01-01 00:00:44.444187 [info] main dispatch thread id from application: 1277 (notify-sample) is: 4 1970-01-01 00:00:44.444187 [info] ## test ## routing_manager_client::start 1970-01-01 00:00:44.444187 [info] shutdown thread id from application: 1277 (notify-sample) is: 5 1970-01-01 00:00:44.444197 [info] io thread id from application: 1277 (notify-sample) is: 6 1970-01-01 00:00:44.444200 [info] io thread id from application: 1277 (notify-sample) is: 1 1970-01-01 00:00:44.444207 [info] rmp::on_message<1277>: 01 00 00 00 00 02 00 00 00 77 12 1970-01-01 00:00:44.444207 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:00:44.444207 [info] ##test 222## received protocol 1970-01-01 00:00:44.444207 [info] ##test 111## received protocol 1970-01-01 00:00:44.444207 [info] ##test## received a message with command 1 1970-01-01 00:00:44.444212 [info] create_local_server: Listening @ /var/vsomeip/vsomeip-1277 1970-01-01 00:00:44.444212 [info] Client 1277 (notify-sample) successfully connected to routing ~> registering.. 1970-01-01 00:00:44.444217 [info] Registering to routing manager @ vsomeip-0 1970-01-01 00:00:44.444234 [info] rmp::on_message<1277>: 05 00 00 66 66 07 00 00 00 00 02 00 00 00 77 12 1970-01-01 00:00:44.444236 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:00:44.444239 [info] ##test 222## received protocol 1970-01-01 00:00:44.444239 [info] ##test 111## received protocol 1970-01-01 00:00:44.444239 [info] ##test## received a message with command 5 1970-01-01 00:00:44.444239 [info] Application/Client 1277 (notify-sample) is registered. Application notify-sample is registered. Setting event (Length=2). 1970-01-01 00:00:45.454198 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:45.454199 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=3). 1970-01-01 00:00:46.464217 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:46.464217 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=4). 1970-01-01 00:00:47.474228 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:47.474228 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=5). 1970-01-01 00:00:48.484241 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:48.484242 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=6). 1970-01-01 00:00:49.494253 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:49.494255 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=7). 1970-01-01 00:00:50.504268 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:50.504268 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=8). 1970-01-01 00:00:51.514282 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:51.514283 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=9). 1970-01-01 00:00:52.524298 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:52.524298 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=1). 1970-01-01 00:00:53.534318 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:00:53.534322 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=2). 1970-01-01 00:01:04.644420 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:01:04.644423 [info] #test 931 : routing_manager_client::on_message:

1970-01-01 00:01:04.644429 [info] rmp::on_message<1277>: 05 00 00 66 66 07 00 00 00 00 02 00 00 00 44 13 1970-01-01 00:01:04.644434 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:01:04.644434 [info] ##test 222## received protocol 1970-01-01 00:01:04.644439 [info] ##test 111## received protocol 1970-01-01 00:01:04.644440 [info] ##test## received a message with command 5 1970-01-01 00:01:04.644448 [info] rmp::on_message<1277>: 12 00 00 44 13 0b 00 00 00 34 12 78 56 65 44 00 ff ff 00 00 1970-01-01 00:01:04.644448 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:01:04.644448 [info] ##test 222## received protocol 1970-01-01 00:01:04.644448 [info] ##test 111## received protocol 1970-01-01 00:01:04.644448 [info] ##test## received a message with command 18 1970-01-01 00:01:04.644448 [info] SUBSCRIBE(1344): [1234.5678.4465:ffff:0]

Setting event (Length=3). 1970-01-01 00:01:05.654442 [info] #test 887 : routing_manager_client::on_message: 1970-01-01 00:01:05.654442 [info] #test 931 : routing_manager_client::on_message: Setting event (Length=4).

Lynn-1997 avatar Dec 12 '24 06:12 Lynn-1997

subscribe-sample log 1970-01-01 00:00:57.578377 [info] Using configuration file: "/mnt/etc/vsomeip.json". 1970-01-01 00:00:57.578383 [info] Parsed vsomeip configuration in 7ms 1970-01-01 00:00:57.578387 [info] Configuration module loaded. 1970-01-01 00:00:57.578387 [info] Security disabled! 1970-01-01 00:00:57.578387 [info] Initializing vsomeip (3.4.10) application "subscribe-sample". 1970-01-01 00:00:57.578387 [info] Instantiating routing manager [Proxy]. 1970-01-01 00:00:57.578387 [info] Client [1344] is connecting to [0] at /var/vsomeip/vsomeip-0 1970-01-01 00:00:57.578387 [info] Application(subscribe-sample, 1344) is initialized (11, 100). Client settings [protocol=UDP] 1970-01-01 00:00:57.578387 [info] Starting vsomeip application "subscribe-sample" (1344) using 2 threads I/O nice 255 1970-01-01 00:00:57.578387 [info] main dispatch thread id from application: 1344 (subscribe-sample) is: 2 1970-01-01 00:00:57.578387 [info] shutdown thread id from application: 1344 (subscribe-sample) is: 3 1970-01-01 00:00:57.578387 [info] ## test ## routing_manager_client::start 1970-01-01 00:00:57.578400 [info] io thread id from application: 1344 (subscribe-sample) is: 4 1970-01-01 00:00:57.578400 [info] io thread id from application: 1344 (subscribe-sample) is: 1 1970-01-01 00:00:57.578407 [info] rmp::on_message<1344>: 01 00 00 00 00 02 00 00 00 44 13 1970-01-01 00:00:57.578408 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:00:57.578408 [info] ##test 222## received protocol 1970-01-01 00:00:57.578408 [info] ##test 111## received protocol 1970-01-01 00:00:57.578408 [info] ##test## received a message with command 1 1970-01-01 00:00:57.578408 [info] create_local_server: Listening @ /var/vsomeip/vsomeip-1344 1970-01-01 00:00:57.578408 [info] Client 1344 (subscribe-sample) successfully connected to routing ~> registering.. 1970-01-01 00:00:57.578408 [info] Registering to routing manager @ vsomeip-0 1970-01-01 00:00:57.578422 [info] rmp::on_message<1344>: 05 00 00 66 66 07 00 00 00 00 02 00 00 00 44 13 1970-01-01 00:00:57.578427 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:00:57.578428 [info] ##test 222## received protocol 1970-01-01 00:00:57.578428 [info] ##test 111## received protocol 1970-01-01 00:00:57.578428 [info] ##test## received a message with command 5 1970-01-01 00:00:57.578428 [info] Application/Client 1344 (subscribe-sample) is registered. Service [1234.5678] is NOT available.

1970-01-01 00:01:04.644434 [info] rmp::on_message<1344>: 05 00 00 66 66 18 00 00 00 02 13 00 00 00 02 00 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:04.644438 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:01:04.644440 [info] ##test 222## received protocol 1970-01-01 00:01:04.644440 [info] ##test 111## received protocol 1970-01-01 00:01:04.644445 [info] ##test## received a message with command 5 1970-01-01 00:01:04.644445 [info] Client [1344] is connecting to [1277] at /var/vsomeip/vsomeip-1277 1970-01-01 00:01:04.644448 [info] ON_AVAILABLE(1344): [1234.5678:0.0] Service [1234.5678] is available.

1970-01-01 00:01:14.744548 [info] rmp::on_message<1344>: 05 00 00 66 66 18 00 00 00 04 13 00 00 00 02 00 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:14.744548 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:01:14.744548 [info] ##test 222## received protocol 1970-01-01 00:01:14.744548 [info] ##test 111## received protocol 1970-01-01 00:01:14.744548 [info] ##test## received a message with command 5 1970-01-01 00:01:14.744548 [info] ON_UNAVAILABLE(1344): [1234.5678:0.0] Service [1234.5678] is NOT available.

1970-01-01 00:01:24.844791 [info] rmp::on_message<1344>: 05 00 00 66 66 18 00 00 00 02 13 00 00 00 02 00 00 00 77 12 09 00 00 00 34 12 78 56 00 00 00 00 00 1970-01-01 00:01:24.844837 [info] ## test ## disable VSOMEIP_ENABLE_COMPAT 1970-01-01 00:01:24.844849 [info] ##test 222## received protocol 1970-01-01 00:01:24.844866 [info] ##test 111## received protocol 1970-01-01 00:01:24.844891 [info] ##test## received a message with command 5 1970-01-01 00:01:24.844918 [info] ON_AVAILABLE(1344): [1234.5678:0.0] Service [1234.5678] is available.

Lynn-1997 avatar Dec 12 '24 06:12 Lynn-1997

I checked the configuration and found that there was indeed a problem with the configuration. I updated the configuration and verified again, but subscribe-sample could not receive SUBSCRIBE ACK.

@joeyoravec

Lynn-1997 avatar Dec 12 '24 06:12 Lynn-1997