Monthly Archives: November 2014

Freedomotic logging for development and debugging Part 2

Leave a reply

Ok, so now we have all our log messages coded in, with appropriate log levels like warn, info, debug. How do we control where they are sent, and how much we want to see?

Freedomotic  uses log4j to handle its logging output and the config file is at framework/freedomotic-core/src/main/resources/log4j.properties

The default at the moment is to log to the console but I want to log some to the console, and some to syslog. While I am developing, the console should show me important errors from all parts of the application and the output to syslog should show me the most granular output of the module I am working on, but also what was sent to the console. This allows me to see any important errors to do with my interactions with other parts of the application straight away on the console where I started the application, but also to see them in-line with my more detailed errors/debugging log via syslog.

Here is my log4j config:

# root logger
log4j.rootLogger=WARN, sysout, SYSLOG

# Output to console
log4j.appender.sysout=org.apache.log4j.ConsoleAppender
log4j.appender.sysout.threshold=WARN
log4j.appender.sysout.layout=org.apache.log4j.PatternLayout
log4j.appender.sysout.layout.ConversionPattern=%-5p <%t> [%C{1}]: %m%n

# Output to Syslog
log4j.appender.SYSLOG=org.apache.log4j.net.SyslogAppender
log4j.appender.SYSLOG.threshold=DEBUG
log4j.appender.SYSLOG.syslogHost=localhost
log4j.appender.SYSLOG.facility=local1
log4j.appender.SYSLOG.facilityPrinting=false
log4j.appender.SYSLOG.layout=org.apache.log4j.PatternLayout
log4j.appender.SYSLOG.layout.conversionPattern=%p <%t> [%C]: %m%n

# Detailed logging of my plugin
log4j.logger.com.freedomotic.plugins.devices.emoncms=DEBUG, SYSLOG
log4j.additivity.com.freedomotic.plugins.devices.emoncms=false
  • Root logger defines all the places I want to log to, and what starting level to send there. I have it set to WARN which means sysout and SYSLOG will get all messages of levels Warning or Error (since I am not expecting levels Critical, Alert or Emergency from my application – they are for the operating system).
  • The Console Appender is defined with a maximum level of WARN. This means that if I were to alter the root logger to DEBUG, I would still only get WARN and worse to it.
  • The Syslog Appender is defines with a maximum level of DEBUG, which means any log entry can potentially get there.
  • I am sending to the syslog facility ‘local1’ on localhost which I have configured in my syslog config to go to its own file (for tidyness).
  • My conversionPattern of ‘%p <%t> [%C]: %m%n’ is slightly different to what I have seen everywhere else on the internet (clue – it has a colon) and is specifically to stop a formatting error which messes up some entries when syslogging on my Mac. (I was getting spurious ‘Unknown’ and some truncation.)
  • The ‘log4j.additivity.com.freedomotic.emoncms=false’ line basically means don’t double-up messages – only add them if they aren’t already there.

So, now I can debug by tailing my log, or better still I can deal with more awkward problems with my favourite log tool, Splunk:

Splunk log analysis

Freedomotic logging for development and debugging

Leave a reply

Debug logOut of the box, Freedomotic logging output currently goes to the console. When you start the application, you see a whole load of messages streaming past you on the screen – very messy.

For me, the logging output should go to a file or what I mean really is that it should be sent to syslog. Ultimately, this is the best way to log applications because putting it into a system designed just for logging means you get access to all the things build specifically for dealing with logging. That probably makes no sense, but I will try to explain by way of my setup.

But firstly, lets look at how the logging happens in Freedomotic. Here is an example of some code from my Resol DL2 plugin:

 LOG.info("Loading Resol DL2 devices..");

..and its easy to see this creates the output of my informative text to the log. Actually I am telling the plugin something else – I have set the log level of ‘info’ which is important too. When you write to the log, you always specify what level you want. Here are the log levels, and Apple’s suggested usage:

  • Emergency (level 0) – The highest priority, usually reserved for catastrophic failures and reboot notices.
  • Alert (level 1) – A serious failure in a key system.
  • Critical (level 2) – A failure in a key system.
  • Error (level 3) – Something has failed.
  • Warning (level 4) Something is amiss and might fail if not corrected.
  • Notice (level 5) – Things of moderate interest to the user or administrator.
  • Info (level 6) – The lowest priority that you would normally log, and purely informational in nature.
  • Debug (level 7) – The lowest priority, and normally not logged except for messages from the kernel.

So, in my case the message is ‘purely informational in nature’ – which it is. But why would I want to log this information? Won’t I be filling the log with pointless chatter?

Now, here is the good bit with proper logging inside an application. I can code in whatever log information at whatever level and then at runtime I can decide what logs I want output from the application.  This means I can put debugging log entries in the code and have these enabled for debugging, but turned off when I am not interested in seeing them.

Next lets see how how this is done..

Eight pointers to help you fix your Sonos for big buildings

1 Reply

Sonos FamilyTaking a working Sonos system and moving to a bigger house should be simple. Sonos ‘just works’, right?

Well, away from the Labs I moved house last year to somewhere with a bit more space. The Sonos came with me and the first zone was unpacked early on the morning after the move as we began the unboxing. Since then it has never worked properly.. until this week.

Over the months I have tried various things to attempt to cure the drop-outs, unresponsive controllers and general grief. Here us some useful info to help anyone in the same situation:

1. SonosNet doesn’t like airwave congestion.

Sonos Preferences - AdvancedSonosNet is the built-in wireless networking of the Sonos system (although you can also get it to use your own wifi now). SonosNet is effectively a private, hidden wifi network and operates in the same air-space as your own wifi, DECT mobile phones and other wireless devices in the same waveband. For this reason, you should ensure your SonosNet is not on the same channel as your Wifi. It is simple to set this from the desktop controller preferences screen. Choices are Chanel 1, 6 or 11 and your Wifi should also be on one of these three.

2. Your wired connections aren’t necessarily being used.

Just because you have added wired connections either between Sonos components, or back to your router / switch doesn’t mean Sonos is using them. The next two points relate to this.

3. Sonos tries to keep ‘hops’ to a minimum, doesn’t necessarily use nodes you think it will.

It seems like Sonos components only like to be a maximum of two hops from each other. This means that if you try to improve coverage by adding say a Bridge Sonos Connect between two other components, it will ignore it because it would add another hop and therefore more latency.

4. Sonos uses Spanning Tree Protocol, so your network switch has to play nicely with this.

This is a bit network-engineer-techy. Because a Sonos system can have multiple connection paths between components, it needs a way to decide which one it will use – and it will only use one path at any given time. It uses something called Spanning Tree Protocol (or STP for short) to do this. If you have components connected via a network switch (which would include one built into your router if it has multiple network ports) then it has to play nicely with STP. By this I mean it either has to implement STP (eg. a managed switch), or pass STP information between connected devices. If it doesn’t do either of these, Sonos will ignore your wired network for connecting Sonos components together and just use SonosNet. Also bear in mind that the STP cost may have to be adjusted, depending on the STP protocol your switch is using.

5. If you have any wired connections, it will be using SonosNet, not your wifi.

'About my Sonos System' screen

‘About my Sonos System’ screen

The recent additional option of connecting your Sonos to your Wifi means that you no longer need the first Sonos component to be wired to your router (or network). However, if any of your Sonos components have a wired connection, the whole system will revert back to SonosNet automatically. This is not obvious – the controller won’t tell you. The best way to confirm this is with the desktop controller – go to ‘About my Sonos System’ which shows you a list of your components. There is an option called WM – 0 means SonosNet, 1 means Wifi. If the Sonos component switches from one to the other, it will reboot. I have seen a component connected via a dodgy network cable continually switch between the two, rebooting each time.

6. Your Sonos system provides diagnostics (but they are not really for you to look at).

Sonos components provide a web interface which can give you a better picture of what is going on. Find the IP of a component using the ‘About my Sonos System’ screen above. Then connect to: http://<your IP:1400/support/review for example on my system: http://192.168.1.102:1400/support/review

On a large system (or one with dodgy networking) this can take a while to return a page, or if your system is really bad, it can fail altogether some of the time. The page will show a list of your components, each of which can be expanded to list a whole load of stuff, most of which I ignore. There are two particularly useful diagnostics though.

At the bottom of the list is Network Matrix. This gives a tabular view of your Sonos components. Each one is listed along the top and down the left of the table. Here is what mine looks like now (ignore the undefined columns which are components currently turned off):

Screen Shot 2014-11-07 at 11.31.51

 

Some important points to look for on your matrix.

  • Look at the colours – green is best, then yellow, orange, and worst is red. These are quality of wireless network to/from the device. An all-grey column/row indicates no wireless connections on that component. You may get for a wired component which is not participating in the SonosNet.
  • Look at the Inbound / Outbound numbers. They give signal strength and go up to 64. Low numbers are worst.
  • Coloured squares in the matrix show what is wirelessly connected to what. This will give you an idea of the path your music data takes.
  • There should only be one empty box per row/column on the matrix. This is where the same component meets on the row/column. If you have more empty boxes, then you have communication problems. Take a look at this matrix. The signal strength is all ok, but there are more blanks than there should be. This will (and does) result in drop-outs, controller delays etc.:

Sonos matrix

7.  Any one poor link in the mesh has the ability to affect the whole system.

Each Sonos zone has a media player which tries to maintain ‘subscriptions’ to all other media players. Also each controller tries to keep tabs of what each zone is up to (think about the Zones screen). If you have one badly connected zone, this will cause problems somewhere, whether its playback, poor controller response etc. The last matrix shows a system in a state where this happens. Everything works great for a while, then picking up a CR200 controller results in playback drop-out from a zone wired directly to the NAS!

8. Sonos provides ongoing support – and its good.

Sonos support have seen all this stuff before, and with access to the diagnostics can pinpoint problems. There is a built-in mechanism for getting this diagnostics to them – the ‘About my Sonos System’ screen (shown above in point 5) has a ‘Submit DIagnostics’ button. This will capture the state of the system and can be used straight after you have a problem to help Sonos Support.

Finally..

From learning all this, out of the many things I tried, I think these are the steps which made it all work in the end:

1. Install a managed switch. Set the STP cost on the Sonos ports to 10 (for 100Mbps) from the default of 19.

2. Wire network connections from the switch to key Sonos components at various points around the house.

3. Make sure the home Wifi was not on the same channel as the Sonos. I ended up with Sonos on 6, and Wifi on 1 and 11 (one at each end of the house).

 Happy Listening!