[SOLVED] Binding to strange address

[DenyAll]

Firstly let me state that this isn't causing any problems that I can tell, however it is strange....

I was looking at my log file when I noticed something strange. The following is an extract of my log file showing the new strategy for recovering the bound IP address:

  Code:

2013-05-02 21:29:38,825 WARN  [DiscoveryAdvertisementNotifier] Cannot acquire NIC for current bound IP address 192.168.0.2, will re-acquire new IP
2013-05-02 21:29:38,826 INFO  [DiscoverySSDPMessageListener] Leaving DiscoverySSDPMessageListener
2013-05-02 21:29:38,826 INFO  [EventDispatcher] Leaving EventDispatcher
2013-05-02 21:29:38,831 INFO  [EventSubscriptionExpirationChecker] Leaving EventSubscriptionExpirationChecker, removing all event subscriptions
2013-05-02 21:29:39,038 WARN  [MultiCastUtils] Could not find NIC with name 'eth6-0'
2013-05-02 21:29:39,038 WARN  [LocalAddressResolverStrategy] Haven't found IP address for NIC eth6-0, will try again 9 times
2013-05-02 21:29:39,095 WARN  [MultiCastUtils] Could not find NIC with name 'eth6-0'
2013-05-02 21:29:39,095 WARN  [LocalAddressResolverStrategy] Haven't found IP address for NIC eth6-0, will try again 8 times
2013-05-02 21:29:44,175 WARN  [MultiCastUtils] Could not find NIC with name 'eth6-0'
2013-05-02 21:29:44,175 WARN  [LocalAddressResolverStrategy] Haven't found IP address for NIC eth6-0, will try again 7 times
2013-05-02 21:29:49,247 WARN  [MultiCastUtils] Could not find NIC with name 'eth6-0'
2013-05-02 21:29:49,247 WARN  [LocalAddressResolverStrategy] Haven't found IP address for NIC eth6-0, will try again 6 times
2013-05-02 21:29:54,316 WARN  [MultiCastUtils] Could not find NIC with name 'eth6-0'
2013-05-02 21:29:54,317 WARN  [LocalAddressResolverStrategy] Haven't found IP address for NIC eth6-0, will try again 5 times
2013-05-02 21:29:59,388 INFO  [Device] Updated bound IP address of Device with UUID: c41c5514-0d79-3774-967b-023b9e31d01f, bound address: 169.254.182.251
2013-05-02 21:29:59,389 INFO  [EventSubscriptionExpirationChecker] Starting EventSubscriptionExpirationChecker
2013-05-02 21:29:59,390 INFO  [EventDispatcher] Starting EventDispatcher
2013-05-02 21:29:59,390 INFO  [DiscoveryAdvertisementNotifier] Starting DiscoveryAdvertisementNotifier
2013-05-02 21:29:59,472 INFO  [DiscoverySSDPMessageListener] Starting DiscoverySSDPMessageListener using interface eth6 (Intel(R) 82566DM-2 Gigabit Network Connection) and address 169.254.182.251, timeout = 0
2013-05-02 21:33:28,498 WARN  [DiscoveryAdvertisementNotifier] Cannot acquire NIC for current bound IP address 169.254.182.251, will re-acquire new IP
2013-05-02 21:33:28,499 INFO  [EventDispatcher] Leaving EventDispatcher
2013-05-02 21:33:28,499 INFO  [EventSubscriptionExpirationChecker] Leaving EventSubscriptionExpirationChecker, removing all event subscriptions
2013-05-02 21:33:28,499 INFO  [DiscoverySSDPMessageListener] Leaving DiscoverySSDPMessageListener
2013-05-02 21:33:28,565 INFO  [Device] Updated bound IP address of Device with UUID: c41c5514-0d79-3774-967b-023b9e31d01f, bound address: 192.168.0.2
2013-05-02 21:33:28,566 INFO  [EventSubscriptionExpirationChecker] Starting EventSubscriptionExpirationChecker
2013-05-02 21:33:28,566 INFO  [EventDispatcher] Starting EventDispatcher

As can be seen, after losing the servers bound IP address (192.168.0.2 static address) probably due to the server awakening from sleep, Serviio shuts down its event dispatcher, listening services etc and then aquires a new address (this is all what it is suppose to do as part of the new binding recovery strategy). The weird thing is, Serviio acquires an address 169.254.182.251 for a short time - this ultimately fails again, it starts the address recovery process again, and then acquires the correct address (192.168.0.2).

I scanned the logs and while this doesn't happen all the time (ie most times it does acquire the correct 192.168.0.2 address straight away), there are adhoc occurances of this interim address being acquired (always the same address - 169.254.182.251), sometimes days apart between occurences. I tried pinging this address and it doesn't exist on my network so am not sure where it is coming from. I googled the address (thinking maybe it was some sort of default address on the NIC) but that didn't help. It is not my external IP address, nor do I have a secondary NIC or run a VPN service. As I stated, it doesn't cause a problem for me.. ultimately this weird address fails, and Serviio recovers on the correct address, but it is very strange and does suggest Serviio is bound to the wrong address for quite a while (four minutes according to the log at least, I haven't noticed it in practice - I would expect Serviio to be unavailable to renderers during this period. It is spasmodic though, so it may be I just haven't noticed it on the renderers).

I note that there are still a few issues on the forum regarding address binding, and that there is some development on this for the next version, so am hoping this info helps feed into your thought process. Not sure if this IP address means anything to anyone, it's certainly not on my network anywhere that I can find.

[will]

196.254.x.x addresses are special addresses that are reserved for when, for example, the DHCP process fails and are actually assigned to by the computer itself http://ask-leo.com/why_cant_i_connect_w ... dress.html

Basically that was assigned straight after sleep and Serviio picked it up, some time later you then got a proper address, which serviio then detected. Maybe Serviio should backoff and try again if it detects a 169.254.x.x address.

To fix this, also set the static IP address in windows settings, not just your router.

[DenyAll]

Thanks will, clearly my google skills need sharpening

I suspected it was something to do with the NIC not being ready in some way (I was close). As you suggest perhaps it can still feed into the Serviio thinking - IMHO it would be better if Serviio continued its recovery attempts until a valid address is found (just not sure how long it would take, suspect it wouldn't be long though). One for zip to think about in his spare time

Thanks again - as you suggest I'll set the static address in the PC as well as the router to fix.
Mark

[zip]

Since 1.2 Serviio doesn't store the IP address, but only the NIC and index of the prefered IP on the NIC (in your case eth6-0). So Serviio doesn't know which IP is valid or not, it just waits for an IP to be available on the preferred NIC and starts using it.

While this should help in cases when IP address changes by DHCP server, in your case it's a bit annoying.

I will read about Will's proposal a bit more, thanks.

I had problems with serviio not being seen by upnp controllers which was resolved by adding a dependency to the serviio service like the one for upnphost (ssdpsrv http). As this is a timing issue, it might resolve your problem.