sony / nmos-cpp

An NMOS (Networked Media Open Specifications) Registry and Node in C++ (IS-04, IS-05)
Apache License 2.0
139 stars 80 forks source link

IS-04 unicast discover more than 2 doesn't work #128

Closed wsneijers closed 2 years ago

wsneijers commented 4 years ago

Hello,

I'm having issues discovering more than 2 registration API's in unicast DNS_SD mode. I am using avahi 0.7 as DNS_SD resolver and have the following BIND config (sorry for the uninitiated :) ):

$ORIGIN .
$TTL 604800     ; 1 week
axon.jtnm.lan         IN SOA  axon.jtnm.lan. root.axon.jtnm.lan. (
                                1          ; serial
                                604800     ; refresh (1 week)
                                86400      ; retry (1 day)
                                2419200    ; expire (4 weeks)
                                604800     ; minimum (1 week)
                                )
                        NS      axon.jtnm.lan.
                        NS      localhost.
                        A       192.168.10.254
$ORIGIN axon.jtnm.lan.
$TTL 0       ; 1 hour

; reg1             A       192.168.10.254

; These lines indicate to clients that this server supports DNS Service Discovery
b._dns-sd._udp  IN  PTR @
lb._dns-sd._udp IN  PTR @

; These lines indicate to clients which service types this server may advertise
_services._dns-sd._udp  PTR _nmos-register._tcp
_services._dns-sd._udp  PTR _nmos-registration._tcp
_services._dns-sd._udp  PTR _nmos-query._tcp
_services._dns-sd._udp  PTR _nmos-system._tcp

; These lines give the fully qualified DNS names to the IP addresses of the hosts which we'd like to discover
; This example uses a domain of 'dns.nmos.tv'. We recommend using a subdomain of a domain name which you own.
reg1    IN  A   192.168.10.1
reg2    IN  A   192.168.10.2
reg3    IN  A   192.168.10.3
reg4    IN  A   192.168.10.4
; query1.dns.nmos.tv.   IN  A   192.168.200.6

; There should be one PTR record for each instance of the service you wish to advertise.
; Here we have one Registration API (_nmos-registration._tcp) and one Query API (_nmos-query._tcp)
; From v1.3, the Registration API switches to use a new name (_nmos-register._tcp)
_nmos-register._tcp PTR reg-api-1._nmos-register._tcp
_nmos-registration._tcp PTR reg-api-1._nmos-registration._tcp
_nmos-query._tcp    PTR qry-api-1._nmos-query._tcp
_nmos-system._tcp   PTR sys-api-1._nmos-system._tcp

_nmos-register._tcp PTR reg-api-2._nmos-register._tcp
_nmos-registration._tcp PTR reg-api-2._nmos-registration._tcp
_nmos-query._tcp    PTR qry-api-2._nmos-query._tcp
_nmos-system._tcp   PTR sys-api-2._nmos-system._tcp

_nmos-register._tcp PTR reg-api-3._nmos-register._tcp
_nmos-registration._tcp PTR reg-api-3._nmos-registration._tcp
_nmos-query._tcp    PTR qry-api-3._nmos-query._tcp
_nmos-system._tcp   PTR sys-api-3._nmos-system._tcp

_nmos-register._tcp PTR reg-api-4._nmos-register._tcp
_nmos-registration._tcp PTR reg-api-4._nmos-registration._tcp
_nmos-query._tcp    PTR qry-api-4._nmos-query._tcp
_nmos-system._tcp   PTR sys-api-4._nmos-system._tcp

; Next we have a SRV and a TXT record corresponding to each PTR above, first the Registration API
; The SRV links the PTR name to a resolvable DNS name (see the A records above) and identify the port which the API runs on
; The TXT records indicate additional metadata relevant to the IS-04 spec
reg-api-1._nmos-register._tcp   SRV 0 0 3210 reg1.axon.jtnm.lan.
reg-api-1._nmos-register._tcp   TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=50" "api_auth=false"
reg-api-2._nmos-register._tcp   SRV 0 0 3210 reg2.axon.jtnm.lan.
reg-api-2._nmos-register._tcp   TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=60" "api_auth=false"
reg-api-3._nmos-register._tcp   SRV 0 0 3210 reg3.axon.jtnm.lan.
reg-api-3._nmos-register._tcp   TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=70" "api_auth=false"
reg-api-4._nmos-register._tcp   SRV 0 0 3210 reg4.axon.jtnm.lan.
reg-api-4._nmos-register._tcp   TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=80" "api_auth=false"

reg-api-1._nmos-registration._tcp   SRV 0 0 3210 reg1.axon.jtnm.lan.
reg-api-1._nmos-registration._tcp   TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=50" "api_auth=false"
reg-api-2._nmos-registration._tcp   SRV 0 0 3210 reg2.axon.jtnm.lan.
reg-api-2._nmos-registration._tcp   TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=60" "api_auth=false"
reg-api-3._nmos-registration._tcp   SRV 0 0 3210 reg3.axon.jtnm.lan.
reg-api-3._nmos-registration._tcp   TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=70" "api_auth=false"
reg-api-4._nmos-registration._tcp   SRV 0 0 3210 reg4.axon.jtnm.lan.
reg-api-4._nmos-registration._tcp   TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=80" "api_auth=false"

; Finally, the SRV and TXT for the Query API
qry-api-1._nmos-query._tcp  SRV 0 0 3210 reg1.axon.jtnm.lan.
qry-api-1._nmos-query._tcp  TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=50" "api_auth=false"
qry-api-2._nmos-query._tcp  SRV 0 0 3210 reg2.axon.jtnm.lan.
qry-api-2._nmos-query._tcp  TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=60" "api_auth=false"
qry-api-3._nmos-query._tcp  SRV 0 0 3210 reg3.axon.jtnm.lan.
qry-api-3._nmos-query._tcp  TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=70" "api_auth=false"
qry-api-4._nmos-query._tcp  SRV 0 0 3210 reg3.axon.jtnm.lan.
qry-api-4._nmos-query._tcp  TXT "api_ver=v1.0,v1.1,v1.2,v1.3" "api_proto=http" "pri=80" "api_auth=false"

sys-api-1._nmos-system._tcp SRV 0 0 10641 reg1.axon.jtnm.lan.
sys-api-1._nmos-system._tcp TXT "api_ver=v1.0" "api_proto=http" "pri=50" "api_auth=false"
sys-api-2._nmos-system._tcp SRV 0 0 10641 reg2.axon.jtnm.lan.
sys-api-2._nmos-system._tcp TXT "api_ver=v1.0" "api_proto=http" "pri=60" "api_auth=false"
sys-api-3._nmos-system._tcp SRV 0 0 10641 reg3.axon.jtnm.lan.
sys-api-3._nmos-system._tcp TXT "api_ver=v1.0" "api_proto=http" "pri=70" "api_auth=false"
sys-api-4._nmos-system._tcp SRV 0 0 10641 reg4.axon.jtnm.lan.
sys-api-4._nmos-system._tcp TXT "api_ver=v1.0" "api_proto=http" "pri=80" "api_auth=false"

However when running nmos-cpp I get the following output: image

I always seem to get one or two, never four. In multicast the mechanism works find. Any thoughts?

garethsb commented 4 years ago

I think it must be something depending on environment as we had no trouble passing the relevant tests in the IS-04-01 test suite of the NMOS Testing Tool in unicast mode. Let's investigate.

wsneijers commented 4 years ago

For some more detail into my dependency versions:

Package Version
CMake 3.14.5
Boost 1.67.0
Websocketpp 0.8.1
C++ REST SDK v2.10.11
Avahi 0.7
nmos-cpp commit 72694755649ecbd9b2db39773555d986eabd254d

I tested on both ARM and x68 (AMD64). Both with the same results.

wsneijers commented 4 years ago

Also, after some more investigations the problem keeps getting stranger. If I test on the same machine with avahi-browse using the following command it does work and I get four responses back:

avahi-browse -a -t -d axon.jtnm.lan

image

If I look at the source of avahi-browse and the 'libcompat' they are almost identical. They mainly differ in the way the underlying avahi client gets called. In the case of avahi-browse with a blocking call in main. In the case of libcompat with callbacks and a time-out. I'll keep digging, but for now I wanted to share what I got thus far.

garethsb commented 4 years ago

Thanks for reporting all these info, it's helpful.

Please would you try running the Node with "logging_level": -40 so we can see a bit more detail of the DNS-SD progress?

garethsb commented 4 years ago

I suspect a caching / timeout issue - Avahi and mDNSResponder have different caching and requery strategies and are also subtly different between unicast DNS-SD and mDNS, and of course it also depends on DNS server, so we may be seeing a combination we've not encountered before.

wsneijers commented 4 years ago

Thanks for reporting all these info, it's helpful.

Please would you try running the Node with "logging_level": -40 so we can see a bit more detail of the DNS-SD progress?

Sure,

2020-03-10 09:14:53.262: info: 3058312384: Ready for connections
*** WARNING *** The program 'nmosd' uses the Apple Bonjour compatibility layer of Avahi.
*** WARNING *** Please fix your application to use the native API of Avahi!
*** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
2020-03-10 09:14:53.309: info: 3037340864: Registered advertisement for: nmos-cpp_node_192-168-10-10:3212._nmos-node._tcp
2020-03-10 09:14:53.314: more info: 2970232000: Trying Registration API discovery for about 1.000 seconds
2020-03-10 09:14:53.314: info: 2970232000: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 09:14:53.315: more info: 3035243712: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 09:14:53.315: more info: 3033146560: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 09:14:53.400: too much info: 3035243712: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.401: too much info: 3035243712: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.403: too much info: 3035243712: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.403: too much info: 3035243712: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.405: too much info: 3035243712: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.406: more info: 3035243712: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:14:53.406: more info: 3028952256: DNSServiceResolve for name: reg-api-2 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:14:53.439: too much info: 3033146560: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.439: too much info: 3033146560: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.440: too much info: 3033146560: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.441: too much info: 3033146560: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.441: more info: 3033146560: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:14:53.442: more info: 3026855104: DNSServiceResolve for name: reg-api-1 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:14:53.475: too much info: 3028952256: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.475: too much info: 3028952256: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.476: too much info: 3028952256: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.479: more info: 3028952256: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-10 09:14:53.479: more info: 3028952256: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-10 09:14:53.484: more info: 3028952256: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-10 09:14:53.485: too much info: 3028952256: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.505: too much info: 3026855104: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.506: too much info: 3026855104: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:53.507: more info: 3026855104: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-10 09:14:53.508: more info: 3026855104: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-10 09:14:53.511: more info: 3026855104: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-10 09:14:53.512: too much info: 3026855104: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:54.315: more info: 3026855104: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 09:14:54.315: more info: 3028952256: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 09:14:54.321: too much info: 3033146560: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:54.322: too much info: 3035243712: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:54.325: info: 2970232000: Discovered 2 Registration API(s)
2020-03-10 09:14:54.325: info: 2970232000: Attempting initial registration
2020-03-10 09:14:54.337: info: 2970232000: Registering nmos-cpp node with the Registration API at: 192.168.10.1:3210
2020-03-10 09:14:54.338: info: 2970232000: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 09:14:54.339: too much info: 2970232000: Sending request
2020-03-10 09:14:54.348: error: 2989106368: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 09:14:54.359: info: 2970232000: Registering nmos-cpp node with the Registration API at: 192.168.10.2:3210
2020-03-10 09:14:54.360: info: 2970232000: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 09:14:54.360: too much info: 2970232000: Sending request
2020-03-10 09:14:57.478: error: 3031049408: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 09:14:57.478: more info: 2970232000: Waiting to retry Registration API discovery for about 0.605 seconds (current backoff limit: 1.000 seconds)
2020-03-10 09:14:58.084: more info: 2970232000: Trying Registration API discovery for about 1.000 seconds
2020-03-10 09:14:58.084: info: 2970232000: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 09:14:58.085: more info: 2993300672: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 09:14:58.085: more info: 2991203520: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 09:14:58.127: too much info: 2993300672: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.127: too much info: 2993300672: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.128: too much info: 2993300672: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.129: too much info: 2993300672: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.130: too much info: 2993300672: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.130: more info: 2993300672: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:14:58.131: more info: 2987009216: DNSServiceResolve for name: reg-api-4 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:14:58.160: too much info: 2991203520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.160: too much info: 2991203520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.161: too much info: 2991203520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.162: too much info: 2991203520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.162: more info: 2991203520: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:14:58.163: more info: 2984912064: DNSServiceResolve for name: reg-api-4 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:14:58.198: too much info: 2987009216: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.199: too much info: 2987009216: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.201: too much info: 2987009216: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.201: more info: 2987009216: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-10 09:14:58.201: more info: 2987009216: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-10 09:14:58.206: more info: 2987009216: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-10 09:14:58.208: too much info: 2987009216: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.228: too much info: 2984912064: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.229: too much info: 2984912064: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:58.229: more info: 2984912064: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-10 09:14:58.229: more info: 2984912064: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-10 09:14:58.233: more info: 2984912064: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-10 09:14:58.234: too much info: 2984912064: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:14:59.085: more info: 2987009216: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 09:14:59.085: more info: 2984912064: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 09:14:59.088: too much info: 2993300672: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:59.091: too much info: 2991203520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:14:59.095: info: 2970232000: Discovered 1 Registration API(s)
2020-03-10 09:14:59.095: info: 2970232000: Attempting initial registration
2020-03-10 09:14:59.111: info: 2970232000: Registering nmos-cpp node with the Registration API at: 192.168.10.4:3210
2020-03-10 09:14:59.111: info: 2970232000: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 09:14:59.112: too much info: 2970232000: Sending request
2020-03-10 09:15:02.278: error: 3047826624: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 09:15:02.279: more info: 2970232000: Waiting to retry Registration API discovery for about 0.144 seconds (current backoff limit: 1.500 seconds)
2020-03-10 09:15:02.423: more info: 2970232000: Trying Registration API discovery for about 1.000 seconds
2020-03-10 09:15:02.423: info: 2970232000: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 09:15:02.424: more info: 2997494976: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 09:15:02.424: more info: 3014272192: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 09:15:02.458: too much info: 2997494976: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.459: too much info: 2997494976: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.459: too much info: 2997494976: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.460: too much info: 2997494976: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.461: more info: 2997494976: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:15:02.461: more info: 3037340864: DNSServiceResolve for name: reg-api-3 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:15:02.488: too much info: 3014272192: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.488: too much info: 3014272192: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.489: too much info: 3014272192: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.490: too much info: 3014272192: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.491: too much info: 3014272192: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.491: more info: 3014272192: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:15:02.492: more info: 2995397824: DNSServiceResolve for name: reg-api-1 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 09:15:02.527: too much info: 3037340864: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.528: too much info: 3037340864: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.530: too much info: 3037340864: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.531: more info: 3037340864: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-10 09:15:02.531: more info: 3037340864: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-10 09:15:02.534: more info: 3037340864: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-10 09:15:02.534: too much info: 3037340864: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.541: too much info: 2995397824: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.546: too much info: 2995397824: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:15:02.547: more info: 2995397824: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-10 09:15:02.547: more info: 2995397824: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-10 09:15:02.549: more info: 2995397824: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-10 09:15:02.550: too much info: 2995397824: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 09:15:03.424: more info: 2995397824: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 09:15:03.424: more info: 3037340864: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 09:15:03.426: too much info: 3014272192: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:03.430: too much info: 2997494976: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 09:15:03.432: info: 2970232000: Discovered 2 Registration API(s)
2020-03-10 09:15:03.433: info: 2970232000: Attempting initial registration
2020-03-10 09:15:03.447: info: 2970232000: Registering nmos-cpp node with the Registration API at: 192.168.10.1:3210
2020-03-10 09:15:03.447: info: 2970232000: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 09:15:03.448: too much info: 2970232000: Sending request
2020-03-10 09:15:03.453: error: 3007980736: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 09:15:03.477: info: 2970232000: Registering nmos-cpp node with the Registration API at: 192.168.10.3:3210
2020-03-10 09:15:03.477: info: 2970232000: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 09:15:03.481: too much info: 2970232000: Sending request
wsneijers commented 4 years ago

Also this same behavior happens with a dedicated DNS server and the testing tool.

garethsb commented 4 years ago

@wsneijers, based on your detailed logs, please would try a quick workaround of editing this line: https://github.com/sony/nmos-cpp/blob/203ecb18108c904a8e53b7171119fa90ed513914/Development/nmos/node_behaviour.cpp#L296

Please try changing the 1 to e.g. 2 or 3.

If that's it, I'll attempt a more elegant fix.

wsneijers commented 4 years ago

@wsneijers, based on your detailed logs, please would try a quick workaround of editing this line:

https://github.com/sony/nmos-cpp/blob/203ecb18108c904a8e53b7171119fa90ed513914/Development/nmos/node_behaviour.cpp#L296

Please try changing the 1 to e.g. 2 or 3.

If that's it, I'll attempt a more elegant fix.

Unfortunately no difference.

garethsb commented 4 years ago

Unfortunately no difference.

Please would you send me the detailed logs for that? Thanks!

wsneijers commented 4 years ago

Yeah sure.

*** WARNING *** The program 'nmosd' uses the Apple Bonjour compatibility layer of Avahi.
*** WARNING *** Please fix your application to use the native API of Avahi!
*** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
ZZ READING thread pid 3058394304 1273
2020-03-10 10:07:30.726: info: 3035325632: Registered advertisement for: nmos-cpp_node_192-168-10-10:3212._nmos-node._tcp
2020-03-10 10:07:30.732: more info: 2970313920: Trying Registration API discovery for about 3.000 seconds
2020-03-10 10:07:30.732: info: 2970313920: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 10:07:30.733: more info: 3031131328: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:07:30.732: more info: 3033228480: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:07:30.752: too much info: 3031131328: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.753: too much info: 3031131328: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.754: too much info: 3031131328: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.754: more info: 3031131328: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:30.770: more info: 3029034176: DNSServiceResolve for name: reg-api-4 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:30.812: too much info: 3033228480: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.812: too much info: 3033228480: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.813: too much info: 3033228480: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.813: too much info: 3033228480: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.816: too much info: 3033228480: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.817: more info: 3033228480: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:30.817: more info: 3026937024: DNSServiceResolve for name: reg-api-4 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:30.835: too much info: 3029034176: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.835: too much info: 3029034176: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.836: too much info: 3029034176: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.838: more info: 3029034176: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-10 10:07:30.838: more info: 3029034176: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-10 10:07:30.842: more info: 3029034176: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-10 10:07:30.845: too much info: 3029034176: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.862: too much info: 3026937024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.863: too much info: 3026937024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:30.864: more info: 3026937024: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-10 10:07:30.864: more info: 3026937024: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-10 10:07:30.867: more info: 3026937024: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-10 10:07:30.867: too much info: 3026937024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:31.771: more info: 3029034176: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:07:31.773: too much info: 3031131328: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:31.774: too much info: 3026937024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:31.775: too much info: 3026937024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:31.776: more info: 3026937024: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:07:31.777: too much info: 3033228480: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:31.779: info: 2970313920: Discovered 1 Registration API(s)
2020-03-10 10:07:31.779: info: 2970313920: Attempting initial registration
2020-03-10 10:07:31.792: info: 2970313920: Registering nmos-cpp node with the Registration API at: 192.168.10.4:3210
2020-03-10 10:07:31.792: info: 2970313920: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:07:31.794: too much info: 2970313920: Sending request
2020-03-10 10:07:34.892: error: 2995479744: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:07:34.893: more info: 2970313920: Waiting to retry Registration API discovery for about 0.737 seconds (current backoff limit: 1.000 seconds)
2020-03-10 10:07:35.632: more info: 2970313920: Trying Registration API discovery for about 3.000 seconds
2020-03-10 10:07:35.632: info: 2970313920: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 10:07:35.633: more info: 2976605376: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:07:35.634: more info: 2974508224: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:07:35.674: too much info: 2976605376: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.674: too much info: 2976605376: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.675: too much info: 2976605376: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.676: too much info: 2976605376: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.677: more info: 2976605376: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:35.677: more info: 3050005696: DNSServiceResolve for name: reg-api-3 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:35.693: too much info: 2974508224: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.694: too much info: 2974508224: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.694: too much info: 2974508224: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.695: too much info: 2974508224: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.695: more info: 2974508224: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:35.696: more info: 3047908544: DNSServiceResolve for name: reg-api-2 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:35.736: too much info: 3050005696: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.737: too much info: 3050005696: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.737: too much info: 3050005696: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.738: more info: 3050005696: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-10 10:07:35.738: more info: 3050005696: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-10 10:07:35.741: more info: 3050005696: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-10 10:07:35.741: too much info: 3050005696: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.755: too much info: 3047908544: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.756: too much info: 3047908544: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:35.756: more info: 3047908544: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-10 10:07:35.756: more info: 3047908544: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-10 10:07:35.759: more info: 3047908544: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-10 10:07:35.760: too much info: 3047908544: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:36.678: more info: 3050005696: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:07:36.681: too much info: 2976605376: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:36.682: too much info: 3047908544: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:36.682: too much info: 3047908544: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:36.684: more info: 3047908544: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:07:36.687: too much info: 2974508224: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:36.689: info: 2970313920: Discovered 2 Registration API(s)
2020-03-10 10:07:36.689: info: 2970313920: Attempting initial registration
2020-03-10 10:07:36.699: info: 2970313920: Registering nmos-cpp node with the Registration API at: 192.168.10.2:3210
2020-03-10 10:07:36.699: info: 2970313920: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:07:36.700: too much info: 2970313920: Sending request
2020-03-10 10:07:39.851: error: 3008062656: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:07:39.861: info: 2970313920: Registering nmos-cpp node with the Registration API at: 192.168.10.3:3210
2020-03-10 10:07:39.861: info: 2970313920: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:07:39.865: too much info: 2970313920: Sending request
2020-03-10 10:07:42.981: error: 3045811392: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:07:42.983: more info: 2970313920: Waiting to retry Registration API discovery for about 0.069 seconds (current backoff limit: 1.500 seconds)
2020-03-10 10:07:43.054: more info: 2970313920: Trying Registration API discovery for about 3.000 seconds
2020-03-10 10:07:43.054: info: 2970313920: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 10:07:43.055: more info: 2978702528: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:07:43.055: more info: 3008062656: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:07:43.091: too much info: 2978702528: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.091: too much info: 2978702528: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.096: too much info: 2978702528: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.096: too much info: 2978702528: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.099: too much info: 2978702528: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.099: more info: 2978702528: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:43.100: more info: 3005965504: DNSServiceResolve for name: reg-api-2 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:43.124: too much info: 3008062656: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.125: too much info: 3008062656: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.125: too much info: 3008062656: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.126: too much info: 3008062656: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.126: more info: 3008062656: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:43.127: more info: 3003868352: DNSServiceResolve for name: reg-api-4 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:43.146: too much info: 3005965504: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.147: too much info: 3005965504: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.148: too much info: 3005965504: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.149: more info: 3005965504: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-10 10:07:43.149: more info: 3005965504: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-10 10:07:43.151: more info: 3005965504: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-10 10:07:43.152: too much info: 3005965504: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.172: too much info: 3003868352: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.176: too much info: 3003868352: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:43.177: more info: 3003868352: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-10 10:07:43.177: more info: 3003868352: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-10 10:07:43.180: more info: 3003868352: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-10 10:07:43.181: too much info: 3003868352: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:44.100: more info: 3005965504: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:07:44.101: too much info: 2978702528: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:44.106: too much info: 3003868352: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:44.107: more info: 3003868352: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:07:44.108: too much info: 3008062656: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:44.110: info: 2970313920: Discovered 2 Registration API(s)
2020-03-10 10:07:44.110: info: 2970313920: Attempting initial registration
2020-03-10 10:07:44.123: info: 2970313920: Registering nmos-cpp node with the Registration API at: 192.168.10.2:3210
2020-03-10 10:07:44.123: info: 2970313920: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:07:44.124: too much info: 2970313920: Sending request
2020-03-10 10:07:47.211: error: 3001771200: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:07:47.221: info: 2970313920: Registering nmos-cpp node with the Registration API at: 192.168.10.4:3210
2020-03-10 10:07:47.222: info: 2970313920: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:07:47.222: too much info: 2970313920: Sending request
2020-03-10 10:07:50.331: error: 2976605376: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:07:50.332: more info: 2970313920: Waiting to retry Registration API discovery for about 0.914 seconds (current backoff limit: 2.250 seconds)
2020-03-10 10:07:51.247: more info: 2970313920: Trying Registration API discovery for about 3.000 seconds
2020-03-10 10:07:51.247: info: 2970313920: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 10:07:51.248: more info: 2972411072: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:07:51.250: more info: 3050005696: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:07:51.286: too much info: 2972411072: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.287: too much info: 2972411072: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.288: too much info: 2972411072: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.288: too much info: 2972411072: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.289: more info: 2972411072: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:51.289: more info: 2974508224: DNSServiceResolve for name: reg-api-2 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:51.307: too much info: 3050005696: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.307: too much info: 3050005696: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.309: too much info: 3050005696: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.310: too much info: 3050005696: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.311: too much info: 3050005696: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.311: more info: 3050005696: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:51.312: more info: 3043714240: DNSServiceResolve for name: reg-api-4 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:07:51.350: too much info: 2974508224: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.351: too much info: 2974508224: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.357: too much info: 2974508224: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.358: more info: 2974508224: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-10 10:07:51.358: more info: 2974508224: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-10 10:07:51.361: more info: 2974508224: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-10 10:07:51.362: too much info: 2974508224: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.364: too much info: 3043714240: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.370: too much info: 3043714240: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:51.371: more info: 3043714240: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-10 10:07:51.371: more info: 3043714240: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-10 10:07:51.375: more info: 3043714240: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-10 10:07:51.375: too much info: 3043714240: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:52.290: more info: 2974508224: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:07:52.292: too much info: 2972411072: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:52.294: too much info: 3043714240: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:52.296: too much info: 3043714240: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:52.297: too much info: 3043714240: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:52.297: too much info: 3043714240: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:07:52.297: more info: 3043714240: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:07:52.299: too much info: 3050005696: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:07:52.301: info: 2970313920: Discovered 2 Registration API(s)
2020-03-10 10:07:52.302: info: 2970313920: Attempting initial registration
2020-03-10 10:07:52.312: info: 2970313920: Registering nmos-cpp node with the Registration API at: 192.168.10.2:3210
2020-03-10 10:07:52.312: info: 2970313920: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:07:52.313: too much info: 2970313920: Sending request
garethsb commented 4 years ago

OK. Please make one more change here: https://github.com/sony/nmos-cpp/blob/203ecb18108c904a8e53b7171119fa90ed513914/Development/mdns/service_discovery_impl.cpp#L73

Again, please try using 2 or 3 rather than 1.

Thanks.

wsneijers commented 4 years ago

OK. Please make one more change here:

https://github.com/sony/nmos-cpp/blob/203ecb18108c904a8e53b7171119fa90ed513914/Development/mdns/service_discovery_impl.cpp#L73

Again, please try using 2 or 3 rather than 1.

Thanks.

Again no luck:

*** WARNING *** The program 'nmosd' uses the Apple Bonjour compatibility layer of Avahi.
ZZ READING thread pid 3058656448 1539
*** WARNING *** Please fix your application to use the native API of Avahi!
*** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
2020-03-10 10:35:33.582: info: 3035587776: Registered advertisement for: nmos-cpp_node_192-168-10-10:3212._nmos-node._tcp
2020-03-10 10:35:33.587: more info: 2970576064: Trying Registration API discovery for about 1.000 seconds
2020-03-10 10:35:33.587: info: 2970576064: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 10:35:33.588: more info: 3033490624: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:35:33.589: more info: 3031393472: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:35:33.607: too much info: 3033490624: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.609: too much info: 3033490624: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.610: too much info: 3033490624: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.610: more info: 3033490624: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:33.631: more info: 3029296320: DNSServiceResolve for name: reg-api-1 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:33.666: too much info: 3031393472: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.666: too much info: 3031393472: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.667: too much info: 3031393472: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.668: too much info: 3031393472: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.668: more info: 3031393472: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:33.668: more info: 3027199168: DNSServiceResolve for name: reg-api-3 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:33.674: too much info: 3029296320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.679: too much info: 3029296320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.679: too much info: 3029296320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.687: too much info: 3029296320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.689: more info: 3029296320: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-10 10:35:33.689: more info: 3029296320: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-10 10:35:33.692: more info: 3029296320: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-10 10:35:33.694: too much info: 3029296320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.704: too much info: 3027199168: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.712: too much info: 3027199168: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:33.712: more info: 3027199168: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-10 10:35:33.712: more info: 3027199168: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-10 10:35:33.714: more info: 3027199168: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-10 10:35:33.715: too much info: 3027199168: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:34.588: more info: 3027199168: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:35:34.591: too much info: 3031393472: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:34.591: too much info: 3029296320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:34.592: too much info: 3029296320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:34.593: more info: 3029296320: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:35:34.595: too much info: 3033490624: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:34.597: info: 2970576064: Discovered 2 Registration API(s)
2020-03-10 10:35:34.597: info: 2970576064: Attempting initial registration
2020-03-10 10:35:34.608: info: 2970576064: Registering nmos-cpp node with the Registration API at: 192.168.10.1:3210
2020-03-10 10:35:34.609: info: 2970576064: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:35:34.611: too much info: 2970576064: Sending request
2020-03-10 10:35:34.621: error: 2995741888: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:35:34.640: info: 2970576064: Registering nmos-cpp node with the Registration API at: 192.168.10.3:3210
2020-03-10 10:35:34.640: info: 2970576064: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:35:34.641: too much info: 2970576064: Sending request
2020-03-10 10:35:37.771: error: 3002033344: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:35:37.772: more info: 2970576064: Waiting to retry Registration API discovery for about 0.363 seconds (current backoff limit: 1.000 seconds)
2020-03-10 10:35:38.137: more info: 2970576064: Trying Registration API discovery for about 1.000 seconds
2020-03-10 10:35:38.137: info: 2970576064: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 10:35:38.138: more info: 2976867520: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:35:38.138: more info: 2989450432: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:35:38.178: too much info: 2976867520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.178: too much info: 2976867520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.179: too much info: 2976867520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.180: too much info: 2976867520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.181: too much info: 2976867520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.182: more info: 2976867520: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:38.182: more info: 2987353280: DNSServiceResolve for name: reg-api-2 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:38.212: too much info: 2989450432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.212: too much info: 2989450432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.212: too much info: 2989450432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.214: too much info: 2989450432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.214: more info: 2989450432: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:38.215: more info: 2972673216: DNSServiceResolve for name: reg-api-3 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:38.239: too much info: 2987353280: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.239: too much info: 2987353280: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.241: too much info: 2987353280: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.242: more info: 2987353280: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-10 10:35:38.242: more info: 2987353280: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-10 10:35:38.244: more info: 2987353280: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-10 10:35:38.245: too much info: 2987353280: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.263: too much info: 2972673216: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.264: too much info: 2972673216: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:38.265: more info: 2972673216: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-10 10:35:38.265: more info: 2972673216: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-10 10:35:38.267: more info: 2972673216: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-10 10:35:38.268: too much info: 2972673216: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:39.138: more info: 2972673216: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:35:39.138: more info: 2987353280: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:35:39.142: too much info: 2989450432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:39.143: too much info: 2976867520: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:39.146: info: 2970576064: Discovered 2 Registration API(s)
2020-03-10 10:35:39.146: info: 2970576064: Attempting initial registration
2020-03-10 10:35:39.159: info: 2970576064: Registering nmos-cpp node with the Registration API at: 192.168.10.2:3210
2020-03-10 10:35:39.159: info: 2970576064: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:35:39.160: too much info: 2970576064: Sending request
2020-03-10 10:35:42.251: error: 3002033344: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:35:42.263: info: 2970576064: Registering nmos-cpp node with the Registration API at: 192.168.10.3:3210
2020-03-10 10:35:42.265: info: 2970576064: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:35:42.268: too much info: 2970576064: Sending request
2020-03-10 10:35:45.371: error: 2993644736: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:35:45.372: more info: 2970576064: Waiting to retry Registration API discovery for about 0.384 seconds (current backoff limit: 1.500 seconds)
2020-03-10 10:35:45.757: more info: 2970576064: Trying Registration API discovery for about 1.000 seconds
2020-03-10 10:35:45.757: info: 2970576064: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-10 10:35:45.758: more info: 3016713408: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:35:45.760: more info: 3014616256: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-10 10:35:45.792: too much info: 3016713408: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.793: too much info: 3016713408: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.794: too much info: 3016713408: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.794: too much info: 3016713408: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.796: too much info: 3016713408: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.796: more info: 3016713408: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:45.797: more info: 3010421952: DNSServiceResolve for name: reg-api-3 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:45.822: too much info: 3014616256: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.822: too much info: 3014616256: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.823: too much info: 3014616256: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.823: too much info: 3014616256: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.827: too much info: 3014616256: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.827: more info: 3014616256: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:45.828: more info: 3008324800: DNSServiceResolve for name: reg-api-1 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-10 10:35:45.859: too much info: 3010421952: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.859: too much info: 3010421952: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.860: too much info: 3010421952: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.861: more info: 3010421952: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-10 10:35:45.861: more info: 3010421952: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-10 10:35:45.863: more info: 3010421952: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-10 10:35:45.864: too much info: 3010421952: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.877: too much info: 3008324800: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.878: too much info: 3008324800: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:45.879: more info: 3008324800: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-10 10:35:45.879: more info: 3008324800: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-10 10:35:45.881: more info: 3008324800: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-10 10:35:45.882: too much info: 3008324800: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 10:35:46.758: more info: 3010421952: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:35:46.759: more info: 3008324800: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-10 10:35:46.761: too much info: 3014616256: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:46.763: too much info: 3016713408: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 10:35:46.765: info: 2970576064: Discovered 2 Registration API(s)
2020-03-10 10:35:46.766: info: 2970576064: Attempting initial registration
2020-03-10 10:35:46.779: info: 2970576064: Registering nmos-cpp node with the Registration API at: 192.168.10.1:3210
2020-03-10 10:35:46.779: info: 2970576064: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:35:46.780: too much info: 2970576064: Sending request
2020-03-10 10:35:46.786: error: 3048170688: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 10:35:46.802: info: 2970576064: Registering nmos-cpp node with the Registration API at: 192.168.10.3:3210
2020-03-10 10:35:46.802: info: 2970576064: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 10:35:46.803: too much info: 2970576064: Sending request
garethsb commented 4 years ago

OK. Thanks again.

One last attempt at a hacky workaround - repeat the change in lines 290 (resolve) and 351 (getaddrinfo).

But I also note from the logs that it looks like the Avahi DNS-SD compatibility layer is taking some shortcuts in the callbacks. It appears (at least for unicast DNS-SD, I think I'd have noticed if it didn't work for mDNS either!) it's not returning the correct interface index (always 0). Also it must not implement the 'more coming' flag (hmm, yes, see https://github.com/lathiat/avahi/pull/18). I suspect the logic in the two nmos-cpp source files I've asked you to touch needs revising a little to handle that.

wsneijers commented 4 years ago

Still no cigar unfortunately.

wsneijers commented 4 years ago

Some more testing. I thought, since it is working with mDNS to test with a small setup to compare logs. Also this might be a nice how-to for others:

In separate terminals I am running the following commands to publish IS-04 registries over mDNS:

avahi-publish-service reg1 _nmos-register._tcp 1000 "api_auth=false" "pri=100" "api_proto=http" "api_ver=v1.0,v1.1,v1.2,v1.3"

avahi-publish-service reg2 _nmos-register._tcp 1001 "api_auth=false" "pri=90" "api_proto=http" "api_ver=v1.0,v1.1,v1.2,v1.3"

avahi-publish-service reg3 _nmos-register._tcp 1002 "api_auth=false" "pri=80" "api_proto=http" "api_ver=v1.0,v1.1,v1.2,v1.3"

avahi-publish-service reg4 _nmos-register._tcp 1003 "api_auth=false" "pri=70" "api_proto=http" "api_ver=v1.0,v1.1,v1.2,v1.3"

avahi-publish-service reg1 _nmos-registration._tcp 1000 "api_auth=false" "pri=100" "api_proto=http" "api_ver=v1.0,v1.1,v1.2,v1.3"

avahi-publish-service reg2 _nmos-registration._tcp 1001 "api_auth=false" "pri=90" "api_proto=http" "api_ver=v1.0,v1.1,v1.2,v1.3"

avahi-publish-service reg3 _nmos-registration._tcp 1002 "api_auth=false" "pri=80" "api_proto=http" "api_ver=v1.0,v1.1,v1.2,v1.3"

avahi-publish-service reg4 _nmos-registration._tcp 1003 "api_auth=false" "pri=70" "api_proto=http" "api_ver=v1.0,v1.1,v1.2,v1.3"

This gives me the same setup, having four registration API's advertised. But then with mDNS. This gives the following console output:

2020-03-10 13:13:18.494: more info: 2970883264: Trying Registration API discovery for about 1.000 seconds
2020-03-10 13:13:18.494: info: 2970883264: Attempting discovery of a Registration API in domain: local
2020-03-10 13:13:18.495: more info: 3054769344: DNSServiceBrowse for regtype: _nmos-register._tcp domain: local on interface: 0
2020-03-10 13:13:18.496: more info: 3042186432: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: local on interface: 0
2020-03-10 13:13:18.535: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.535: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.537: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.537: more info: 3054769344: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg1 for regtype: _nmos-register._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.537: more info: 3037992128: DNSServiceResolve for name: reg1 regtype: _nmos-register._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.558: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.559: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.560: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.560: more info: 3042186432: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg2 for regtype: _nmos-registration._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.561: more info: 3044283584: DNSServiceResolve for name: reg2 regtype: _nmos-registration._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.594: too much info: 3037992128: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.594: too much info: 3037992128: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.595: too much info: 3037992128: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.596: more info: 3037992128: After DNSServiceResolve, DNSServiceResolveReply got host: axonnl-303.local. port: 1000
2020-03-10 13:13:18.596: more info: 3037992128: getaddrinfo for hostname: axonnl-303.local.
2020-03-10 13:13:18.599: more info: 3037992128: Using getaddrinfo, got address: 192.168.10.22 for host: axonnl-303.local.
2020-03-10 13:13:18.600: too much info: 3037992128: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.602: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.603: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.603: more info: 3054769344: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg2 for regtype: _nmos-register._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.604: more info: 2981369024: DNSServiceResolve for name: reg2 regtype: _nmos-register._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.620: too much info: 3044283584: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.620: too much info: 3044283584: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.621: too much info: 3044283584: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.622: more info: 3044283584: After DNSServiceResolve, DNSServiceResolveReply got host: axonnl-303.local. port: 1001
2020-03-10 13:13:18.622: more info: 3044283584: getaddrinfo for hostname: axonnl-303.local.
2020-03-10 13:13:18.625: more info: 3044283584: Using getaddrinfo, got address: 192.168.10.22 for host: axonnl-303.local.
2020-03-10 13:13:18.626: too much info: 3044283584: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.631: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.633: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.633: more info: 3042186432: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg3 for regtype: _nmos-registration._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.633: more info: 3035894976: DNSServiceResolve for name: reg3 regtype: _nmos-registration._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.672: too much info: 2981369024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.673: too much info: 2981369024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.674: too much info: 2981369024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.675: more info: 2981369024: After DNSServiceResolve, DNSServiceResolveReply got host: axonnl-303.local. port: 1001
2020-03-10 13:13:18.675: more info: 2981369024: getaddrinfo for hostname: axonnl-303.local.
2020-03-10 13:13:18.678: more info: 2981369024: Using getaddrinfo, got address: 192.168.10.22 for host: axonnl-303.local.
2020-03-10 13:13:18.679: too much info: 2981369024: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.680: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.680: more info: 3054769344: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg3 for regtype: _nmos-register._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.681: more info: 3033797824: DNSServiceResolve for name: reg3 regtype: _nmos-register._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.710: too much info: 3035894976: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.710: too much info: 3035894976: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.711: too much info: 3035894976: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.713: too much info: 3035894976: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.714: more info: 3035894976: After DNSServiceResolve, DNSServiceResolveReply got host: axonnl-303.local. port: 1002
2020-03-10 13:13:18.714: more info: 3035894976: getaddrinfo for hostname: axonnl-303.local.
2020-03-10 13:13:18.717: more info: 3035894976: Using getaddrinfo, got address: 192.168.10.22 for host: axonnl-303.local.
2020-03-10 13:13:18.718: too much info: 3035894976: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.723: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.723: more info: 3042186432: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg4 for regtype: _nmos-registration._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.724: more info: 3029603520: DNSServiceResolve for name: reg4 regtype: _nmos-registration._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.772: too much info: 3033797824: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.772: too much info: 3033797824: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.772: too much info: 3033797824: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.773: more info: 3033797824: After DNSServiceResolve, DNSServiceResolveReply got host: axonnl-303.local. port: 1002
2020-03-10 13:13:18.773: more info: 3033797824: getaddrinfo for hostname: axonnl-303.local.
2020-03-10 13:13:18.776: more info: 3033797824: Using getaddrinfo, got address: 192.168.10.22 for host: axonnl-303.local.
2020-03-10 13:13:18.777: too much info: 3033797824: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.777: too much info: 3029603520: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.778: too much info: 3029603520: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.779: more info: 3029603520: After DNSServiceResolve, DNSServiceResolveReply got host: axonnl-303.local. port: 1003
2020-03-10 13:13:18.779: more info: 3029603520: getaddrinfo for hostname: axonnl-303.local.
2020-03-10 13:13:18.780: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.780: more info: 3054769344: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg4 for regtype: _nmos-register._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.781: more info: 3027506368: DNSServiceResolve for name: reg4 regtype: _nmos-register._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.784: more info: 3029603520: Using getaddrinfo, got address: 192.168.10.22 for host: axonnl-303.local.
2020-03-10 13:13:18.785: too much info: 3029603520: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.798: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.798: more info: 3042186432: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg1 for regtype: _nmos-registration._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.799: more info: 3021214912: DNSServiceResolve for name: reg1 regtype: _nmos-registration._tcp. domain: local. on interface: 3
2020-03-10 13:13:18.831: too much info: 3027506368: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.832: too much info: 3027506368: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.833: too much info: 3027506368: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.833: more info: 3027506368: After DNSServiceResolve, DNSServiceResolveReply got host: axonnl-303.local. port: 1003
2020-03-10 13:13:18.834: more info: 3027506368: getaddrinfo for hostname: axonnl-303.local.
2020-03-10 13:13:18.837: more info: 3027506368: Using getaddrinfo, got address: 192.168.10.22 for host: axonnl-303.local.
2020-03-10 13:13:18.837: too much info: 3027506368: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.840: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.840: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.841: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.841: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.843: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.843: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.844: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.844: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.845: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.845: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.845: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.846: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.846: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.846: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.847: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.847: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.847: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.850: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.851: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.862: too much info: 3021214912: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.863: too much info: 3021214912: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.864: too much info: 3021214912: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.864: more info: 3021214912: After DNSServiceResolve, DNSServiceResolveReply got host: axonnl-303.local. port: 1000
2020-03-10 13:13:18.864: more info: 3021214912: getaddrinfo for hostname: axonnl-303.local.
2020-03-10 13:13:18.867: more info: 3021214912: Using getaddrinfo, got address: 192.168.10.22 for host: axonnl-303.local.
2020-03-10 13:13:18.868: too much info: 3021214912: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.869: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.870: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.870: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.871: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.871: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.873: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.873: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.873: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.874: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.874: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.874: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.875: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.875: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.876: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.876: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.876: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.877: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.879: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.880: too much info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.882: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:18.882: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:19.495: more info: 3054769344: After DNSServiceBrowse, DNSServiceProcessResult timed out or was cancelled
2020-03-10 13:13:19.498: too much info: 3042186432: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-10 13:13:19.502: info: 2970883264: Discovered 4 Registration API(s)
2020-03-10 13:13:19.504: info: 2970883264: Attempting initial registration
2020-03-10 13:13:19.515: info: 2970883264: Registering nmos-cpp node with the Registration API at: 192.168.10.22:1003
2020-03-10 13:13:19.516: info: 2970883264: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 13:13:19.520: too much info: 2970883264: Sending request
2020-03-10 13:13:19.529: error: 2996049088: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 13:13:19.539: info: 2970883264: Registering nmos-cpp node with the Registration API at: 192.168.10.22:1002
2020-03-10 13:13:19.539: info: 2970883264: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 13:13:19.543: too much info: 2970883264: Sending request
2020-03-10 13:13:19.549: error: 2981369024: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 13:13:19.558: info: 2970883264: Registering nmos-cpp node with the Registration API at: 192.168.10.22:1001
2020-03-10 13:13:19.559: info: 2970883264: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 13:13:19.560: too much info: 2970883264: Sending request
2020-03-10 13:13:19.564: error: 3025409216: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 13:13:19.587: info: 2970883264: Registering nmos-cpp node with the Registration API at: 192.168.10.22:1000
2020-03-10 13:13:19.587: info: 2970883264: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-10 13:13:19.590: too much info: 2970883264: Sending request
2020-03-10 13:13:19.595: error: 2975077568: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-10 13:13:19.598: more info: 2970883264: Waiting to retry Registration API discovery for about 0.918 seconds (current backoff limit: 1.500 seconds)

So indeed this does work. Also I also see the interface number is different for DNSServiceResolve. What I also observe is that there are a lot more DNSServiceProcessResult succeeded messages.

garethsb commented 4 years ago

So indeed this does work. Also I also see the interface number is different for DNSServiceResolve. What I also observe is that there are a lot more DNSServiceProcessResult succeeded messages.

Right, there are some obvious differences in behaviour between mDNS and unicast DNS-SD.

Most of those DNSServiceProcessResult calls are presumably effectively no-ops, not actually calling the callback with a result (as noted here - https://github.com/sony/nmos-cpp/blob/203ecb18108c904a8e53b7171119fa90ed513914/Development/mdns/service_discovery_impl.cpp#L98).

The test system that I have set up for unicast DNS-SD testing is built with mDNSResponder. It passes all the relevant test cases.

I will set up another environment with Avahi to replicate and debug here. You could try building with mDNSResponder (and the unicast DNS-SD patches) as described in the Dependencies - DNS Service Discovery docs or demo'd in the Travis CI script:

https://github.com/sony/nmos-cpp/blob/203ecb18108c904a8e53b7171119fa90ed513914/.travis.yml#L90-L99

wsneijers commented 4 years ago

I found a clue, maybe @garethsb-sony you know what goes wrong. If I set the interface_id in resolve (service_discovery_impl.cpp line 288) to 3, matching the index in the multicast resolve, it seams to work. I then get four registries. So for some reason this interface index not getting set correctly impacts the resolve function.

Quick update: It seems that avahi returns kDNSServiceInterfaceIndexLocalOnly in the browse_reply callback when doing unicast resolve instead of the interface index.

wsneijers commented 4 years ago

I think I found the issue, at-least for avahi. @garethsb-sony could you check if the resolution I found works for mDNSResponder as well?

Long story but here we go :). Avahi has issues with interface index 0. For some reason, with unicast DNS, it does not allow it to resolve all the interfaces. If you pass interface index -1 (kDNSServiceInterfaceIndexLocalOnly), which is what gets returned by avahi in callbacks in unicast resolves it returns kDNSServiceErr_Unsupported. However if you remove that check with the patch below (avahi 0.7) and make a small change in nmos-cpp it does work:

nmos-cpp service_discovery_impl.cpp from: image

To: image

Avahi patch:

--- a/compat.c
+++ b/compat.c
@@ -618,7 +618,7 @@
         return kDNSServiceErr_BadParam;
     *ret_sdref = NULL;

-    if (interface == kDNSServiceInterfaceIndexLocalOnly || flags != 0) {
+    if (flags != 0) {
         AVAHI_WARN_UNSUPPORTED;
         return kDNSServiceErr_Unsupported;
     }
@@ -743,7 +743,7 @@
         return kDNSServiceErr_BadParam;
     *ret_sdref = NULL;

-    if (interface == kDNSServiceInterfaceIndexLocalOnly || flags != 0) {
+    if (flags != 0) {
         AVAHI_WARN_UNSUPPORTED;
         return kDNSServiceErr_Unsupported;
     }

I don't know why this error check is in avahi. Because, according to the Apple spec, it is supported. Though I don't know if the behavior is correct because it should then only resolve local entries for the machine and not go onto the network. At least for now, if anyone wants it, this method seems to work. However I think it does require more work (possibly a fix in Avahi) to make it work permanently.

And if you are still here (good job sticking through it) I want to add that this workaround isn't based on a hunch. I actually discovered this when looking at how 'avahi-browse' works. Since it works fine. Granted it doesn't use the compatibility layer, but it does use all the same internal calls. So a quick 1-on-1. Avahi uses D-BUS to communicate from client to daemon. Knowing that we can easily spy on what it is doing with the command dbus-monitor --system:

image

So it also returns -1 for the interface index when doing a unicast DNS browse.

garethsb commented 4 years ago

Good progress, well done! I'm sorry I haven't had time to investigate this deeply yet.

But I'm not convinced by your patch, sorry.

The issue here is the Avahi compatibility layer mapping between AvahiIfIndex which supports one special value AVAHI_IF_UNSPEC (-1) meaning any/all interfaces, and the Bonjour API which supports two special values kDNSServiceInterfaceIndexAny (0) meaning "do the right thing" or any/all interfaces and kDNSServiceInterfaceIndexLocalOnly (-1).

The compatibility layer callbacks from Avahi (e.g. service_browser_callback) don't map AVAHI_IF_UNSPEC (-1) back to kDNSServiceInterfaceIndexAny (0), so they appeared as kDNSServiceInterfaceIndexLocalOnly (-1). That's why we have the make_interface_id call.

So having received AVAHI_IF_UNSPEC (-1) from browse callback, we send kDNSServiceInterfaceIndexAny (0) into the resolve call. This passes the internal Avahi check without the change you are proposing, but if you look a few lines further down, you'll see it gets turned back into AVAHI_IF_UNSPEC (-1), e.g.

https://github.com/lathiat/avahi/blob/6242e5f0fe001b7de2ccaa9431db279b2ee76b83/avahi-compat-libdns_sd/compat.c#L764

wsneijers commented 4 years ago

Good progress, well done! I'm sorry I haven't had time to investigate this deeply yet.

But I'm not convinced by your patch, sorry.

The issue here is the Avahi compatibility layer mapping between AvahiIfIndex which supports one special value AVAHI_IF_UNSPEC (-1) meaning any/all interfaces, and the Bonjour API which supports two special values kDNSServiceInterfaceIndexAny (0) meaning "do the right thing" or any/all interfaces and kDNSServiceInterfaceIndexLocalOnly (-1).

The compatibility layer callbacks from Avahi (e.g. service_browser_callback) don't map AVAHI_IF_UNSPEC (-1) back to kDNSServiceInterfaceIndexAny (0), so they appeared as kDNSServiceInterfaceIndexLocalOnly (-1). That's why we have the make_interface_id call.

So having received AVAHI_IF_UNSPEC (-1) from browse callback, we send kDNSServiceInterfaceIndexAny (0) into the resolve call. This passes the internal Avahi check without the change you are proposing, but if you look a few lines further down, you'll see it gets turned back into AVAHI_IF_UNSPEC (-1), e.g.

https://github.com/lathiat/avahi/blob/6242e5f0fe001b7de2ccaa9431db279b2ee76b83/avahi-compat-libdns_sd/compat.c#L764

Good point, Didn't see that one. But still it has something to do with that index somewhere I think. I'll keep digging.

wsneijers commented 4 years ago

Pfff. You know those moments when you spend 3 days figuring something out, going through every layer. Then to find that it is as simple as changing a 1 to a 0......

More to the point. When I change the following line (service_discovery_impl.cpp line 291) from:

const auto earliest_timeout_ = std::chrono::seconds(0 == interface_id ? 1 : 0);

to:

const auto earliest_timeout_ = std::chrono::seconds(0);

It seems to work. @garethsb-sony Can you explain why this is the case? I remember us changing it for this issue to 2 and 3. I don't fully understand what this change implies.

garethsb commented 4 years ago

OK... Can you confirm that's the only change you now have? None of the other changes to timeout values in mdns/service_discovery_impl.cpp or nmos/mdns.cpp?

There's a reason for that condition on 0 == interface_id, but let's confirm what we have...

wsneijers commented 4 years ago

I'm doing a full clean build now to verify. Should take around an hour or so. But yeah I think this is the only change.

garethsb commented 4 years ago

And if you could send me (email or here) the detailed log both with and without that single change, that'd be much appreciated (sorry, I've still not got to setting this up locally).

wsneijers commented 4 years ago

Sure. I will put it here, as reference for others.

Without change:

Start up node operation (including the mDNS advertisements) once all NMOS APIs are open
2020-03-12 09:52:15.987: info: 3058586816: Ready for connections
*** WARNING *** The program 'nmosd' uses the Apple Bonjour compatibility layer of Avahi.
ZZ READING thread pid 3058586816 29122
*** WARNING *** Please fix your application to use the native API of Avahi!
*** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
2020-03-12 09:52:16.033: info: 3035518144: Registered advertisement for: nmos-cpp_node_192-168-10-10:3212._nmos-node._tcp
2020-03-12 09:52:16.037: more info: 2970506432: Trying Registration API discovery for about 1.000 seconds
2020-03-12 09:52:16.037: info: 2970506432: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-12 09:52:16.038: more info: 3033420992: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-12 09:52:16.039: more info: 3031323840: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-12 09:52:16.058: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.058: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.062: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.062: more info: 3033420992: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:52:16.086: more info: 3029226688: DNSServiceResolve for name: reg-api-3 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:52:16.120: too much info: 3029226688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.120: too much info: 3029226688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.125: too much info: 3029226688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.127: more info: 3029226688: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-12 09:52:16.128: more info: 3029226688: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-12 09:52:16.132: more info: 3029226688: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-12 09:52:16.134: too much info: 3029226688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.136: too much info: 3031323840: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.137: too much info: 3031323840: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.137: too much info: 3031323840: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.139: too much info: 3031323840: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.139: more info: 3031323840: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:52:16.139: more info: 3027129536: DNSServiceResolve for name: reg-api-2 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:52:16.146: too much info: 3029226688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.147: too much info: 3029226688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.162: too much info: 3027129536: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.169: too much info: 3027129536: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:16.170: more info: 3027129536: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-12 09:52:16.170: more info: 3027129536: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-12 09:52:16.172: more info: 3027129536: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-12 09:52:16.173: too much info: 3027129536: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.037: more info: 3027129536: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-12 09:52:17.040: too much info: 3031323840: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.042: too much info: 3029226688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.042: more info: 3029226688: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-12 09:52:17.043: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.045: info: 2970506432: Discovered 2 Registration API(s)
2020-03-12 09:52:17.046: info: 2970506432: Attempting initial registration
2020-03-12 09:52:17.057: info: 2970506432: Registering nmos-cpp node with the Registration API at: 192.168.10.2:3210
2020-03-12 09:52:17.058: info: 2970506432: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-12 09:52:17.059: too much info: 2970506432: Sending request
2020-03-12 09:52:17.069: error: 2995672256: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-12 09:52:17.081: info: 2970506432: Registering nmos-cpp node with the Registration API at: 192.168.10.3:3210
2020-03-12 09:52:17.081: info: 2970506432: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-12 09:52:17.082: too much info: 2970506432: Sending request
2020-03-12 09:52:17.087: error: 3016643776: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-12 09:52:17.088: more info: 2970506432: Waiting to retry Registration API discovery for about 0.759 seconds (current backoff limit: 1.000 seconds)
2020-03-12 09:52:17.849: more info: 2970506432: Trying Registration API discovery for about 1.000 seconds
2020-03-12 09:52:17.849: info: 2970506432: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-12 09:52:17.850: more info: 3033420992: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-12 09:52:17.851: more info: 3027129536: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-12 09:52:17.885: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.886: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.887: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.888: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.889: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.889: more info: 3033420992: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:52:17.890: more info: 3010352320: DNSServiceResolve for name: reg-api-1 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:52:17.917: too much info: 3027129536: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.918: too much info: 3027129536: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.918: too much info: 3027129536: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.919: too much info: 3027129536: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.919: more info: 3027129536: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:52:17.920: more info: 3008255168: DNSServiceResolve for name: reg-api-4 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:52:17.935: too much info: 3010352320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.936: too much info: 3010352320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.937: more info: 3010352320: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-12 09:52:17.937: more info: 3010352320: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-12 09:52:17.939: more info: 3010352320: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-12 09:52:17.940: too much info: 3010352320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.943: too much info: 3010352320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.943: too much info: 3010352320: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.965: too much info: 3008255168: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.966: too much info: 3008255168: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:17.967: more info: 3008255168: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-12 09:52:17.967: more info: 3008255168: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-12 09:52:17.969: more info: 3008255168: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-12 09:52:17.970: too much info: 3008255168: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:52:18.850: more info: 3010352320: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-12 09:52:18.853: too much info: 3033420992: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:18.851: more info: 3008255168: After DNSServiceResolve, DNSServiceProcessResult timed out or was cancelled
2020-03-12 09:52:18.855: too much info: 3027129536: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:52:18.860: info: 2970506432: Discovered 2 Registration API(s)

With change:

Start up node operation (including the mDNS advertisements) once all NMOS APIs are open
2020-03-12 09:53:52.797: info: 3058713792: Ready for connections
*** WARNING *** The program 'nmosd' uses the Apple Bonjour compatibility layer of Avahi.
ZZ READING thread pid 3058713792 29229
*** WARNING *** Please fix your application to use the native API of Avahi!
*** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
2020-03-12 09:53:52.843: info: 3035645120: Registered advertisement for: nmos-cpp_node_192-168-10-10:3212._nmos-node._tcp
2020-03-12 09:53:52.846: more info: 2970633408: Trying Registration API discovery for about 1.000 seconds
2020-03-12 09:53:52.846: info: 2970633408: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-12 09:53:52.847: more info: 3033547968: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-12 09:53:52.849: more info: 3031450816: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-12 09:53:52.867: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.869: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.870: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.870: more info: 3033547968: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:52.887: more info: 3029353664: DNSServiceResolve for name: reg-api-4 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:52.922: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.923: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.923: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.924: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.924: more info: 3031450816: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:52.925: more info: 3027256512: DNSServiceResolve for name: reg-api-2 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:52.930: too much info: 3029353664: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.935: too much info: 3029353664: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.935: too much info: 3029353664: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.945: too much info: 3029353664: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.947: more info: 3029353664: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-12 09:53:52.947: more info: 3029353664: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-12 09:53:52.950: more info: 3029353664: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-12 09:53:52.955: too much info: 3029353664: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.963: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.964: more info: 3033547968: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:52.964: more info: 3025159360: DNSServiceResolve for name: reg-api-3 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:52.987: too much info: 3027256512: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.987: too much info: 3027256512: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.988: too much info: 3027256512: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.992: too much info: 3027256512: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.992: more info: 3027256512: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-12 09:53:52.993: more info: 3027256512: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-12 09:53:52.995: more info: 3027256512: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-12 09:53:52.996: too much info: 3027256512: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.998: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:52.999: more info: 3031450816: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:52.999: more info: 3023062208: DNSServiceResolve for name: reg-api-4 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.009: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.009: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.011: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.012: more info: 3025159360: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-12 09:53:53.012: more info: 3025159360: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-12 09:53:53.015: more info: 3025159360: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-12 09:53:53.016: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.017: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.019: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.019: more info: 3033547968: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.020: more info: 3020965056: DNSServiceResolve for name: reg-api-1 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.055: too much info: 3023062208: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.056: too much info: 3023062208: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.057: too much info: 3023062208: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.058: more info: 3023062208: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-12 09:53:53.058: more info: 3023062208: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-12 09:53:53.060: more info: 3023062208: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-12 09:53:53.061: too much info: 3023062208: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.062: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.064: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.065: more info: 3031450816: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.065: more info: 3018867904: DNSServiceResolve for name: reg-api-1 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.091: too much info: 3020965056: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.091: too much info: 3020965056: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.092: too much info: 3020965056: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.093: too much info: 3020965056: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.094: more info: 3020965056: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-12 09:53:53.094: more info: 3020965056: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-12 09:53:53.097: more info: 3020965056: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-12 09:53:53.097: too much info: 3020965056: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.099: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.099: more info: 3033547968: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.100: more info: 3016770752: DNSServiceResolve for name: reg-api-2 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.131: too much info: 3018867904: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.131: too much info: 3018867904: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.132: too much info: 3018867904: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.133: too much info: 3018867904: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.133: more info: 3018867904: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-12 09:53:53.133: more info: 3018867904: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-12 09:53:53.136: more info: 3018867904: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-12 09:53:53.137: too much info: 3018867904: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.139: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.139: more info: 3031450816: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.140: more info: 3014673600: DNSServiceResolve for name: reg-api-3 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:53.168: too much info: 3016770752: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.169: too much info: 3016770752: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.169: too much info: 3016770752: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.170: too much info: 3016770752: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.171: more info: 3016770752: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-12 09:53:53.171: more info: 3016770752: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-12 09:53:53.173: more info: 3016770752: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-12 09:53:53.174: too much info: 3016770752: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.176: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.177: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.177: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.178: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.178: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.179: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.179: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.180: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.181: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.182: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.183: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.183: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.184: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.186: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.186: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.188: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.189: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.190: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.192: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.196: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.207: too much info: 3014673600: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.207: too much info: 3014673600: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.210: too much info: 3014673600: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.211: more info: 3014673600: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-12 09:53:53.211: more info: 3014673600: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-12 09:53:53.213: more info: 3014673600: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-12 09:53:53.214: too much info: 3014673600: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.215: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.216: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.216: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.217: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.217: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.218: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.218: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.219: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.220: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.221: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.221: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.222: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.224: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.225: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.225: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.226: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.226: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.228: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.229: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.229: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.230: too much info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:53.847: more info: 3031450816: After DNSServiceBrowse, DNSServiceProcessResult timed out or was cancelled
2020-03-12 09:53:53.847: more info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult timed out or was cancelled
2020-03-12 09:53:53.851: info: 2970633408: Discovered 4 Registration API(s)
2020-03-12 09:53:53.851: info: 2970633408: Attempting initial registration
2020-03-12 09:53:53.861: info: 2970633408: Registering nmos-cpp node with the Registration API at: 192.168.10.1:3210
2020-03-12 09:53:53.861: info: 2970633408: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-12 09:53:53.863: too much info: 2970633408: Sending request
2020-03-12 09:53:53.874: error: 2985313472: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-12 09:53:53.885: info: 2970633408: Registering nmos-cpp node with the Registration API at: 192.168.10.2:3210
2020-03-12 09:53:53.885: info: 2970633408: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-12 09:53:53.886: too much info: 2970633408: Sending request
2020-03-12 09:53:53.891: error: 3010479296: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-12 09:53:53.901: info: 2970633408: Registering nmos-cpp node with the Registration API at: 192.168.10.3:3210
2020-03-12 09:53:53.902: info: 2970633408: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-12 09:53:53.902: too much info: 2970633408: Sending request
2020-03-12 09:53:53.907: error: 2997896384: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-12 09:53:53.918: info: 2970633408: Registering nmos-cpp node with the Registration API at: 192.168.10.4:3210
2020-03-12 09:53:53.918: info: 2970633408: Requesting registration creation for node: fe1a44be-be22-50f4-af82-0bce701a82a7
2020-03-12 09:53:53.919: too much info: 2970633408: Sending request
2020-03-12 09:53:53.924: error: 3018867904: Registration request HTTP error: Failed to connect to any resolved endpoint [generic:113]
2020-03-12 09:53:53.926: more info: 2970633408: Waiting to retry Registration API discovery for about 0.349 seconds (current backoff limit: 1.000 seconds)
2020-03-12 09:53:54.276: more info: 2970633408: Trying Registration API discovery for about 1.000 seconds
2020-03-12 09:53:54.276: info: 2970633408: Attempting discovery of a Registration API in domain: axon.jtnm.lan
2020-03-12 09:53:54.277: more info: 3014673600: DNSServiceBrowse for regtype: _nmos-register._tcp domain: axon.jtnm.lan on interface: 0
2020-03-12 09:53:54.278: more info: 3033547968: DNSServiceBrowse for regtype: _nmos-registration._tcp domain: axon.jtnm.lan on interface: 0
2020-03-12 09:53:54.316: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.324: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.325: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.326: more info: 3033547968: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.327: more info: 3010479296: DNSServiceResolve for name: reg-api-3 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.334: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.335: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.335: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.340: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.341: more info: 3014673600: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.341: more info: 3008382144: DNSServiceResolve for name: reg-api-2 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.400: too much info: 3010479296: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.400: too much info: 3010479296: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.401: more info: 3010479296: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-12 09:53:54.401: more info: 3010479296: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-12 09:53:54.404: more info: 3010479296: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-12 09:53:54.405: too much info: 3010479296: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.406: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.406: too much info: 3008382144: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.406: more info: 3033547968: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.407: more info: 3006284992: DNSServiceResolve for name: reg-api-4 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.407: too much info: 3008382144: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.408: more info: 3008382144: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-12 09:53:54.408: more info: 3008382144: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-12 09:53:54.410: more info: 3008382144: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-12 09:53:54.411: too much info: 3008382144: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.422: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.423: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.423: more info: 3014673600: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-4 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.424: more info: 3004187840: DNSServiceResolve for name: reg-api-4 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.451: too much info: 3006284992: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.452: too much info: 3006284992: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.453: too much info: 3006284992: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.454: more info: 3006284992: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-12 09:53:54.454: more info: 3006284992: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-12 09:53:54.457: more info: 3006284992: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-12 09:53:54.458: too much info: 3006284992: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.459: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.459: more info: 3033547968: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.460: more info: 3002090688: DNSServiceResolve for name: reg-api-1 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.484: too much info: 3004187840: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.484: too much info: 3004187840: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.485: too much info: 3004187840: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.485: more info: 3004187840: After DNSServiceResolve, DNSServiceResolveReply got host: reg4.axon.jtnm.lan. port: 3210
2020-03-12 09:53:54.486: more info: 3004187840: getaddrinfo for hostname: reg4.axon.jtnm.lan.
2020-03-12 09:53:54.488: more info: 3004187840: Using getaddrinfo, got address: 192.168.10.4 for host: reg4.axon.jtnm.lan.
2020-03-12 09:53:54.489: too much info: 3004187840: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.490: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.491: more info: 3014673600: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-3 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.491: more info: 2999993536: DNSServiceResolve for name: reg-api-3 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.502: too much info: 3002090688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.503: too much info: 3002090688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.504: too much info: 3002090688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.504: more info: 3002090688: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-12 09:53:54.505: more info: 3002090688: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-12 09:53:54.507: more info: 3002090688: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-12 09:53:54.508: too much info: 3002090688: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.516: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.517: more info: 3033547968: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-2 for regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.517: more info: 3025159360: DNSServiceResolve for name: reg-api-2 regtype: _nmos-registration._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.550: too much info: 2999993536: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.550: too much info: 2999993536: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.553: too much info: 2999993536: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.554: more info: 2999993536: After DNSServiceResolve, DNSServiceResolveReply got host: reg3.axon.jtnm.lan. port: 3210
2020-03-12 09:53:54.554: more info: 2999993536: getaddrinfo for hostname: reg3.axon.jtnm.lan.
2020-03-12 09:53:54.556: more info: 2999993536: Using getaddrinfo, got address: 192.168.10.3 for host: reg3.axon.jtnm.lan.
2020-03-12 09:53:54.557: too much info: 2999993536: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.560: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.560: more info: 3014673600: After DNSServiceBrowse, DNSServiceBrowseReply got service: reg-api-1 for regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.561: more info: 2997896384: DNSServiceResolve for name: reg-api-1 regtype: _nmos-register._tcp. domain: axon.jtnm.lan. on interface: 0
2020-03-12 09:53:54.591: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.592: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.593: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.594: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.595: more info: 3025159360: After DNSServiceResolve, DNSServiceResolveReply got host: reg2.axon.jtnm.lan. port: 3210
2020-03-12 09:53:54.595: more info: 3025159360: getaddrinfo for hostname: reg2.axon.jtnm.lan.
2020-03-12 09:53:54.599: more info: 3025159360: Using getaddrinfo, got address: 192.168.10.2 for host: reg2.axon.jtnm.lan.
2020-03-12 09:53:54.600: too much info: 3025159360: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.602: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.602: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.605: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.605: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.606: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.606: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.606: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.607: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.607: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.608: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.609: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.609: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.610: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.610: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.611: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.611: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.612: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.614: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.614: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.636: too much info: 2997896384: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.637: too much info: 2997896384: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.637: more info: 2997896384: After DNSServiceResolve, DNSServiceResolveReply got host: reg1.axon.jtnm.lan. port: 3210
2020-03-12 09:53:54.637: more info: 2997896384: getaddrinfo for hostname: reg1.axon.jtnm.lan.
2020-03-12 09:53:54.640: more info: 2997896384: Using getaddrinfo, got address: 192.168.10.1 for host: reg1.axon.jtnm.lan.
2020-03-12 09:53:54.641: too much info: 2997896384: After DNSServiceResolve, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.643: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.644: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.644: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.644: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.645: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.645: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.645: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.646: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.646: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.648: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.648: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.649: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.649: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.650: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.650: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.650: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.657: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.657: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.657: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.658: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:54.660: too much info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:55.278: more info: 3014673600: After DNSServiceBrowse, DNSServiceProcessResult timed out or was cancelled
2020-03-12 09:53:55.281: too much info: 3033547968: After DNSServiceBrowse, DNSServiceProcessResult succeeded
2020-03-12 09:53:55.284: info: 2970633408: Discovered 4 Registration API(s)
garethsb commented 4 years ago

OK, I finally have some time to test this. Firstly, we have jsut replicated our usual Linux build on a clean environment using mDNSResponder, and proved that we can pass the IS-04-01 tests with DNS_SD_MODE = 'unicast' in Config.py.

nmos-cpp-node was lanuched as follows:

./nmos-cpp-node "{\"domain\":\"testsuite.nmos.tv\", \"http_port\":1080, \"logging_level\":-40, \"discovery_backoff_max\":15}"

We'll now build up the environment using Avahi instead of mDNSResponder!

garethsb commented 4 years ago

Having now built up the environment with Avahi, I can confirm that I see test failures with the test suite config DNS_SD_MODE='unicast' in three test cases, IS0401Test.test_15, test_16 and test_21. So at least that reproduces what you experienced, @wsneijers!

However, I tried the change you reported worked for you (https://github.com/sony/nmos-cpp/issues/128#issuecomment-598099844), and it only makes things worse for me, with many more test failures, starting from test_02.

I will attempt to debug.

wsneijers commented 4 years ago

Nice to see it at least reproduces (half the battle is won :) ). However it strange, I tested it on multiple targets: embbedded (ARM system), my PC (x86) and a laptop (x86). They all worked after doing that modification. Though I'm not on the latest develop!

garethsb commented 4 years ago

This was a fresh x64 Ubuntu 18.04 with Avahi 0.7.

By the way, did you try mDNSResponder, Wesley?

wsneijers commented 4 years ago

Okay, strange I test as well on ubuntu 18.04 with avahi 0.7 (tried 0.8 as well, no difference). I did not test with mDNSResponder. Is this still something you want? Because my preference goes out for avahi in the end (because the target product already uses it).

garethsb commented 4 years ago

Up to you. DNS-SD has been by far the most development time-wasting technology in the NMOS stack. So many gotchas. Finally, we've been using mDNSResponder with success (with our patches) on all platforms in multicast and unicast. So, although I'll try to make Avahi build work also, it's not top priority.

MarcusMathiassen commented 4 years ago

Hi, has there been any updates on this? We came across the same problem running Centos 7 and Avahi with test 15, 16 and 21 failing, and came to the same solution as above const auto earliest_timeout_ = std::chrono::seconds(0); in resolve. Any timeout above 0 seconds also results in the tests failing.

garethsb commented 4 years ago

HI @MarcusMathiassen. In the background, we are looking at a refactor of the way we package and use the dns_sd.h API in nmos-cpp, which may help with this issue. However, there are so many corner cases in the different environments to work through, we won't switch to it until it's undergone enough testing. In the mean time, as above, I believe building nmos-cpp with mDNSResponder is one way to pass all the tests reliably.

garethsb commented 2 years ago

I've recently spent some time looking at this again.

In my current environment I found that the change that @wsneijers suggested and @MarcusMathiassen confirmed also works for me, provided that I also modify config.json "registration_request_max" to be sufficiently less than the NMOS Testing Tool's DNS_SD_ADVERT_TIMEOUT. This is to handle the case where the Testing Tool's (non-existent) timeout mock Registry is tried by the Node early in the fail-over process.

Marcus identified that changing the earliest timeout to any value greater than 0 also resulted in the tests failing. I confirmed this, if we mean whole seconds, but found that e.g. milliseconds(100) worked fine. This made me realise that the underlying issue is that when set to 1 second, the extra pass round the resolve loop was using up the entire time to the earliest timeout of the browse function.

The original change to make the earliest timeout non-zero in 6a26bdbb6d8ea636b4f81672663384b063bca2ff was required to resolve an issue reported by @rhastie outlined in https://github.com/sony/nmos-cpp/issues/99#issuecomment-566758202, which as far as I remember was reproduced when using mDNSResponder, in order to ensure at least one fully-resolved response was achieved using DNSServiceResolve and DNSServiceGetAddrInfo.

There are a lot of combinations to test, since although we're using _dnssd.h as an attempt to abstract the DNS-SD implementation, it's behaviour clearly depends on many things:

Without refactoring the use of _dnssd.h entirely, maybe the following would help:

0 < earliest timeout in mdns_details::getaddrinfo <= earliest timeout in mdns_details::resolve < earliest timeout in mdns_details::browse < maximum acceptable response time e.g. 1 second

We have to remember that the NMOS Testing Tool advertises 6 registries, which is not likely to be common in real deployments, and also that testing with everything running on a single host is not going to give response delays representative of a real deployment.

It would help if the GitHub Actions testing were updated to include some unicast DNS-SD configurations at least. Then I propose trying with e.g. mdns_details::getaddrinfo earliest timeout = 100-200ms, mdns_details::resolve earliest timeout = 100-200ms and mdns_details::browse earliest timeout = 1 second.

@lo-simon Do you have some time to help work on this?

lo-simon commented 2 years ago

resolved by #250