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

[Lynn-1997]

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

[joeyoravec]

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

[Lynn-1997]

{
"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]

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]

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]

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]

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