Fixing the BBC's removal of HLS streams in MinimServer

The BBC has decided to remove the streams I was using via MinimServer to play R3 through my impressive stereo. This was fixed by

• Switching to a different URL in the Playlist 

#EXTINF:-1,[+R3;aac,48000] BBC Radio 3

http://as-hls-ww-live.akamaized.net/pool_904/live/ww/bbc_radio_three/bbc_radio_three.isml/bbc_radio_three-audio%3d320000.norewind.m3u8

• Installing a pre-compiled instance of ffmpeg 
• Putting it in the minimserver/opt/bin directory
• Adding a converter to the MinimStream config to use it

• Restarting everything

Hurrah. At least until the next idiotic BBC action.

Rune has stopped playing playlists via upmpdcli :-9

I don't know when this happened, but with the various OpenHome clients I have (Lumin, Kazoo, UpPlay), but it appears that both my Rune-based renders are no longer working properly. When presented with a playlist via a UPnP client, they play the first track and then stop. Subsequent tracks can be played by direct selection, but they don't then roll to the next one. Bummer.

I've had a look with Wireshark, but the UPnP protocol is pretty impenetrable from scratch. Yes, I can see things happening, and kind of decode them, but it's not simple. I am using upmpdcli which comes standard with Rune to interface mpd to OpenHome/DLNA/UPnP. The Rune player works from the web interface, with the entirely different playlist mechanism working fine. So - I think there's something afoot with the UPnPClient-upmpdcli interface.

Research on the upmpdcli website reveals that the code is currently at version 1.4.12 - my version of Rune (which is hardly supported at all!) is at something mad like 0.13 !!

I have choices:

• Go for another version of Rune - there is a much more recent version, with newer versions of everything, that has a truly horrible UI; frankly, I'd rather not have a UI, other than a means of simplifying restarts if things are hung up
• Try to install a newer version of upmpdcli, which means 
• Learning about ArchLinux pacman and so on
• Possibly recompiling upmpdcli for ARM (!)
• ... And thereby breaking the Rune I have
• Switch to another product
• Volumio - meh. 
• Moode ?
• picoreplayer - Logitech, not UPnP

Urgh. I happen to have a RPi with Volumio already installed, let's check that out first. Volumio has an OTA update facility, so I'll crank that up and see what happens.

OK, did that. It does now provide the continuous album play, but... the Tidal interface appears to be broken! I have to check back on my previous efforts in that respect.

Update - The Following Day!

In order to try things out independently , I installed upmpdcli on my Linux box, and pointed it at the Volumio MPD. It worked fine as a native OH renderer, showing up in all the right places, and controlling the Volumio MPD. Result, at least in terms of understanding the way things work, and providing further options (none of which seemed very useful!). The latest upmpdcli supports Tidal, BUT doesn't have a valid current API key/token, so although the Linn Kazzo CP shows it supports Tidal, you can't login.

Since I want Tidal (I'm paying for it!), and I don't want to give additional money Volumio for their Tidal interface to work when I'm fine with Kazoo, Lumin as CPs, and BubbleUPnPServer as a serverside streaming interface, I need to get things working as they were i.e.

                Linn Kazoo/Lumin CP
                         | | |
    ---------------------  | ------------------
    |                      |                  |
minimserver MS ------------|----------  Rune MPD+UPnP renderers
                 -----------                  |
                 |  |--------------------------       
    BubbleUPnPServer OH+Tidal

Much more investigation followed, into BubbleUPnPServer especially, trying to get consistent naming etc. so I could track what was seeing what and so on. However, couldn't seem to get BubbleUPnPServer (BUS) to "see" the new render instances i.e Volumio and the standalone upmpdcli instance. I spent ages tail-ing the log file, doing various restarts, with no luck...

Until, at one point, all the flipping upmpdcli instances became visible!! I was then able to add some test OpenHome renderer proxies in BUS, and they worked well, including Tidal. Then, just for the hell of it, I tried multiple tracks in a playlist for the renderers that previously hadn't worked, and they did. Damn. Anyway, after many hours, I'm back were I started, except that things work, and I know a lot more about how this setup actually works than I did! I might write something more about all this at some point.

I also loaded BubbleUPnP onto my Amazon Fire aka Android tablet, and it seems pretty handy. Other than a restriction on playlist length (16 max in the free version) and a certain tendency to overwrite the queue, it works ok, and of course it's easier to read on the bigger screen. I might even persuade my wife to use it!

Rune, bubbleUPnPServer, Linn, Names and Rooms

It's been a while since I've posted anything in this blog, largely because my RPi audio has just been working. However, a week or two (maybe more, grr) I thought it would be interesting to check out if Rune has moved on, and see if there were any interesting new features available.

I cautiously downloaded a fork of Rune, with a revised UI, and tried that, on a new SD card - yeah, that's a handy way to test things without changing the original.

Yuck. Hated the UI, and none of the features were interesting. I then tried a later version of the original Rune - didn't seem to work consistently with the Linn Kazoo OpenHome CP programs I have (iOS app and MacOs). Drat. I upgraded, or at least, re-installed the bubbleupnpserver I have installed on a separate RPi running the media server using minimserver, in an attempt to make it work better. Nope.

Back in went the original SD card. Things seemed to work... except they didn't. Songs would cut out and then recover, or not, completely randomly. Now, I had used an Apple AirPort to provide a wired-seeming interface to the RPi, rather than rely on the RPi built-in wireless. So I ran a cable from room A to room B, and ditched the Airport. That seemed to fix the outages... but still the Tidal streaming service, from the Bubble UPnP Server, wouldn't work, and the Linn Kazoo instances couldn't always find the renderers... Argh. Very Boring Indeed, especially as there didn't seem to be a rhyme or reason to this.

Looking at logs, it seemed that the Bubble Server and RPi Rune instance would get out of step, and the Linn Kazoos would be asking for the wrong IP address. Weird, as the IP address of the RPi Rune renderer is a dynamically advertised property, using DNLA/OpenHome protocols. I tried snooping packets using tcpdump and wireshark, but that wasn't much help, largely because I couldn't see the server <> Rune <> Kazoo packets because I wasn't running wireshark on the right box.

A bit of googling, and looking at the configuration file for upmpdcli, the program that provides the DNLA/UPnP interface for Rune, and I realised a number of things:

• The mysterious "Main Room" device that Kazoo could see is actually the native upmpdcli, which provides an OpenHome interface itself, offering a Room where the Product is located i.e. a potential grouping of multiple OH devices e.g. preamp, renderer,  whose name is configured in the config file using ohproductroom
• Bubble UPnP Server allows configuration of the Product and the Room, as separate fields. I had always used the same value for these - why not? Didn't seem to make any difference - but clearly there was confusion about the devices/rooms I was using
• upmpdcli also offeres a Tidal interface!! Handy to know...
• Kazoo detects the Room name, not the Product name!! Weird, but I suppose it makes sense if your devices/products have to be grouped together for control of a single audio stream

So - I

• reinstalled Bubble UPnP Server, just because...
• renamed the upmpdcli DNLA service on my Rune instance, so it would be redetected, and also altered the Room name, just in case
• redetected the Rune DNLA service in BUPnPS, and used different names for the OH Product and Room fields

Now things appear to work. For the time being anyway. Let's see how long they work for...

Incidentally, I tried using the two different OH interfaces available, from MacOs Kazoo:

• Bubble UPnP Server OH wrapper for upmpdcli DNLA
• upmpdcli native OH interface

They both work, but only the Bubble currently supports Tidal - I think there's more configuration required for upmpdcli. However, if I start a track from the media server in one, then switch to the other, it all gets a bit confused, and I'm not really surprised. I think I'll stick to the Bubble one for now, at least until I've worked out how to configure upmpdcli properly!

Update

It appears that the Rune version that I'm running has a very old upmpdcli, which does not include the Tidal interface. A little investigation reveals that because Rune is based on ArchLinux, rather than Raspbian (as Volumio is), the Debian apt-get mechanism for upgrading it doesn't work - ArchLinux uses PacMan, which an entirely different mechanism. Bugger. Almost makes one consider using a raw Raspbian, with an installation of MPD and umpmdcli to build one's won headless version. After all, I never really use the web interface for selecting music, although I do check it to see what's working sometimes!

RPi for in-car video player - tasks remaining

Things are going ok with this project.

A reminder of requirements:

1. Play on composite video screens using 4 wire connection (from RPi)
2. Play DVDs from DVDs, using USB DVD player
3. Web interface for controlling the gizmo
4. Play stuff from Airplay or equivalent
5. Provide an in-car wireless hub so it's easy to get into from phones etc.

What remains to be done?

1. Attach DVD drive, check that DVDs play
1. This might require purchasing an MPEG-2 key from RPi - £2.50 :-p
2. Connect composite video screen, see how that works
3. Fiddle with Airplay, but I suspect this is going to hard with Apple's proprietary protocol
4. Do some power supply testing - I'm getting a lightning flash symbol on the upper right of the screen, which is an indication that the power supply is occasionally inadequate!
1. This should include in-car testing from a USB supply thingy

Then package it all up somehow. Marv.

RPi for in-car video player Part Deux

Saved the previous SD card image, switched to LibreElec. Boots straight into Kodi, had to add lcd_rotate=2 to config.txt on the SD card itself (not inside Linux) to get it to be the right way up for the stupid Pi Official LCD Stand, which has the LCD the wrong way up. Bah.

Is this better? It's exactly the same... but let's check out the networking!

It appears to use connman, whatever that is... No sign of /etc/network/interfaces!

Checked connman man entry etc. Interesting. It appears to be possible to remove an interface from connman management, which presumably means one could then do something else with it.

Update: Wow!! There's a wireless AP option on the System/Networks page. Enabled it, can see AP on my iPhone and MBP, but it won't accept the passphrase!! Grrr...

Update: lots of looking for this and that - turned on logging, looked in journalctl, found a suspicious error, which I Googled... no joy. Then I switched on connman logging (touch /storage/.config/debug_connman) and rebooted. Now it works!! Coolio.

RPi for in-car video player

The g-kids have some DVD players in the car, so I thought it might be interesting to try building an RPi-based video streamer that would have some more flexibility in control and outputs.

Requirements:

1. Play on composite video screens using 4 wire connection (from RPi)
2. Play DVDs from DVDs, using USB DVD player
3. Web interface for controlling the gizmo
4. Play stuff from Airplay or equivalent
5. Provide an in-car wireless hub so it's easy to get into from phones etc.

Checked out the Kodi options, and they are:

1. Packaged distro - I'm concerned they won't meet requirement 5, because I won't be able to fiddle with the distro enough
1. LibreElec
2. OpenElec
3. OSMC
2. Raspbian with Kodi installed - maximum flexibility, so let's go with that.

Experimenting with my LCD-equipped RPi stack, including Digi+ ripoff digital interface...

Installed NOOBS on a 8GB SD card, opted for latest Raspbian install

Did 

• sudo apt-get update
• sudo apt-get install kodi - Version 17.4 Krypton apparently
• waited for a bit...
• plugged in USB keyboard
• now trying to get some media installed somehow!
• Tried adding Minimserver uPnP server, but entire system crashed!! Or at least, screen blanked and nothing happened...
• Added USB_Storage from file server, as Pictures, and can now show a folder in a rotating slideshow - hurray!
• Tried adding Server as music storage - crashed again!
• Turns out it's not crashing - the display is blanking when running Kodi over the desktop, so did the following:
• sudo vi /etc/lightdm/lightdm.conf
• [Seat:*] uncommented and edited linexserver-command=X -s 0 dpms
• This appears to have done the trick!

Requirement 3 - Web Interface: Enabled web interface Kodi options, connected to raspberrypi.local/8080 and bingo! UI here... It allows for playing stuff, but not a system-level interface, for that you need to go directly to the server. I'm really struggling with this... it's not intuitive at all! For example, I've added my USB memory stick to the library (I think) in Kodi, but I can't see my movies in the WebUI.

OK, added my Server/Music folder as a library and I can see it on the WebUI now. Hurray. Still can't see the content of the USB stick - it claims "no content" when it tries to index it! Strange.

Requirement X - Play stuff: Currently still trying to add some media files - trying a USB stick which I'll mount. Takes a long time to copy many GB! Works fine - added two movies, currently playing one - see above for indexing/access.

Requirement 2 - Play DVDs: Configuration menu provides for DVD playing, so all I need is an appropriate USB-connected DVD/Blueray drive! Ordered one off eBay for £8, should arrive Friday.

Requirement 1 - Connect using composite video 4 wires: I don't have a cable, but I do have an elderly in-car DVD player inherited off the guys with composite video in. I'll get a cable and try it out - the only problem is likely to be getting the connections right, so I might need 3.5 jack to 4 RCA and v.v. to enable easy switching around. Bought 3.5mm -> RCA Female, RCA Male -> 3.5mm on eBay, so can easily connect anything to anything.

Requirement 4 - Airplay: Just tried that out from MacBook Pro running iTunes and Mad Men DVD rip from HD. Oops. MBP said it was trying to play on Kodi, but Kodi froze, then stiffed - it's now restarted (?) and looking for me to tell it what to do. But the WebUI did declare it was playing airplay.m4v, which is pretty interesting.

Requirement 5 - Wifi hub: Using this helpful note,  I did

• sudo apt-get install hostapd udhcpd

And then did a couple of other things, but noticed that the /etc/networks/interfaces file was nothing like the example, and after some delving in the /etc/dhcpcd.conf file, decided I needed a better documented approach that matched my RPi config!! Bugger.

This looks like a better approach... I note that this also assumes there are useful lines in the interfaces config file, unlike mine! Hey ho...

• The usual
• sudo apt-get update
• sudo apt-get dist-upgrade
• As previously with some extras
• sudo apt-get install dnsmasq hostapd
• Stop the new services...
• sudo systemctl stop dnsmasq
• sudo systemctl stop hostapd
• Disable current wlan0 handling
• sudo nano /etc/dhcpcd.conf
• Add deny interfaces wlan0 somewhere...
• Saved as /etc/dhcpcd.conf.new
• Time to try editing the interfaces file!
• Nope, that really isn't working. The dhcpcd demon quits declaring that it's not going to get involved because someone has configured a static IP address in interfaces - guilty as charged! Another post explains exactly why - apparently the latest Raspbian version (Stretch) has radically changed how the networking is organised, and none of the old stuff works. I can concur.

So - what to do? Frankly, Linux networking is a nightmare. It is almost impossible to untangle, and not explained anywhere sensible, with so many levels of indirection and files it's really not obvious what does what. Hmm... I wonder if one of the Kodi-specific builds is simpler? They are only Linux after all.

RPi 7" Touch Screen - it's alive!

I've been living with the rather lashed up setup of the RPi and IQAudio DAC, albeit in a nice shiny black box, in conjunction with the Linkwitz LXMinis and accompanying miniDSP 2x4 for maybe six months now. The main drawbacks, if there are any, are

• Wife finds it impossible to use, because she hasn't really got a handle on using a browser or the Kazoo app to select music to play, and really she'd like to have the facility for putting on a CD, as we once could :-o
• Turning off the music at source without having the phone or laptop to hand whilst walking through the stereo listening room is a pain - yeah, bit of a 1st world problem, but Lumin, Kazoo etc are relatively slow to get their act together
• Whilst connecting the CD player (which has an analogue output only, and 5 pin DIN at that, bloody Naim with their silly ideas about hifi) is possible, it currently involves unplugging the RPi from the miniDSP and plugging the CD player into it instead. Boring.

It would be nice (as well as interesting :-) ) to have a handy interface with the renderer. So why not a nice RPi Official © RPi Inc 7" Touch Screen Display? Coming right up, sir...

Bought from thepihut.com, along with a nifty black plexiglass stand, for about £65 (ouch, but hey...), arrived in a couple of days. 

The screen is chunky, heavy, black bezel. It has a PCB with the serial-parallel electronics bolted on the back. You have to attach the RPi to it with the usual threaded standoffs, and then there's the option of powering it all by

1. Connecting USB supply to the screen, and linking power to the RPi with a short USB-USB Micro cable
2. Connecting USB supply to the RPi, and using the supplied patch-type cables to connect RPi GPIO 5.5v/Gnd to screen 5.5v/Gnd inputs

Looks like using a hat DAC prevents option 2, because the DAC uses the GPIO pins...

Screen standing with stand :-) - cool!

The screen and stand are easily assembled, once you take the attached PCB off the screen! The stand is multi-layer plexiglass, and one layer is a bit tricky to get the right way round, but there's only two ways to put it so...

I struggled a bit with the flat ribbon cable to connect the RPi display connector to the screen connector, but I find that with all these flat cable connectors - it's hard to see which side of the connecter the cable goes in!

Rear of screen and stand - note re-attached PCB

I removed the SPDIF interface board from my sample RPi3 and attached it, using the GPIO pin power connections. A quick power up - screen on, RPi on, BUT... the screen was just showing varicoloured vertical lines. Yuck. Power off, retry connection to RPi, power up, and hooray! This time the screen worked, and ended up showing a terminal prompt. Lovely...

Rear view showing attached/connected RPi

I then used a browser on my laptop to point to the Rune instance on the RPi (which was running a previously set up image...) and configured "Start a browser on HDMI/TFT" in the Settings. Restart... and...

Screen showing Rune browser interface!

Result!!

A quick test of the touch capabilities - all the screen touch points and selections work fine, as defined by the browser page. The lower ones are a tiny bit tricky to hit, but it's easy to adjust one's touch point :-). Fantastic, and ridiculously easy. Maybe I should have tried something harder, like integrating a cheap display...

Is Bluetooth useful?

I have "acquired" (translation: I have borrowed from Code Club) a couple of BBC micro:bits. These have a Bluetooth stack on them, which can be used to connect to other devices. The uBits are pretty capable microcontrollers, with lots of low power features, and if they were connected to sensors etc. they could easily transmit information to more powerful devices, like... a Raspberry Pi! Quite what I'll do with this yet I don't know, but in the best open-ended fashion, let's see if I can get anything working before we worry about an interesting application. Code Club Kids might like this...

First thing is to identify a suitable RPi. I'll be using the server, all the others are configured with the Rune image.

Next, check on the installation of BlueZ, the Linux Bluetooth stack. Need to update the distro and firmware - apt-get update, apt-get upgrade, apt-get dist-upgrade. Hurrah!

Testing... Running bluetoothctl, but it can't see any Bluetooth controllers. More research - try installing pi-bluetooth, already installed. BlueZ also already installed, but bluem not... apt running hard on this one! Still no controllers visible. Reboot....

Bingo. Controller available!

pi@server:~ $ sudo bluetoothctl

[NEW] Controller B8:27:EB:BF:C4:1D server [default]

[NEW] Device 48:74:6E:CD:96:2A John's iPhone

As can be seen, my phone is visible. Hurrah. Can't connect though. However, I'm interested as much in connecting the uBit, let's find out about that.

Super useful blog here - Martin W is a Bluetooth aficionado and has lots of info and help on Bt generally and RPi/uBit specifically.

Bluetooth Roles: (credited to Martin Woolley, at the above blog)

Bluetooth devices will play one of 4 possible Bluetooth roles as defined by that masterpiece, the Bluetooth core specification. The four roles are called

1. Peripheral
2. Central
3. Broadcaster
4. Observer

These terms are part of "GAP", the Generic Access Profile, which is a part of the Bluetooth architecture.

A Peripheral (like a uBit, smartphones with specific software) advertises, inviting and (perhaps) accepting connections from Central devices. 'Advertising' means transmitting small amounts of data, quite frequently, which other Bluetooth devices can receive and act upon if they think the advertising device is of interest.

A Central (smartphones) device scans, looking for advertising packets and based on their content, may decide to connect to a device it thinks is suitable.

A Broadcaster (Bluetooth beacon) is like a peripheral in that it advertises but it does not accept connections. It's sole purpose is to advertise.

An Observer (e.g. a beacon app on a smartphone, alerting one to special offers etc.) scans and processes advertising packets but never tries to connect to another device.

More Ripping Yarns

Background

In this post, I wrote about ripping CDs and the apparently large number of errors you get when you actually bother to check for them. I actually asked the question "Why don't programs provided on CD fail because they have so many bit errors that the code is defective?".  I discussed this with some ex-work colleagues over lunch yesterday, and we reckoned something else must be going on... A bit of research reveals that that is in fact the case!

The underlying storage mechanism is the same for CD-DA and CD-ROM (and its derivatives), but essentially, the "file system" is different.

Firstly, all CDs use the same encoding scheme - 

The Red Book specifies the physical parameters and properties of the CD, the optical "stylus" parameters, deviations and error rate, modulation system (eight-to-fourteen modulation, EFM) and error correction facility (cross-interleaved Reed–Solomon coding, CIRC), and the eight subcode channels. These parameters are common to all compact discs and used by all logical formats, such as CD-ROM. (wikipedia). 

The CIRC encoding system basically wraps lots of extra bits around the data as part of the encoding. It also scatters the logical audio frames around a number of physical frames, so that disk faults can be more easily recovered from, since they will generally degrade recoverably a number of logical frames and not obliterate the one with the error.

However, CD-ROM, as opposed to CD Digital Audio, adds in more error checksums and another layer of error correction... because it is assumed that computer data cannot be interpolated like audio data, but must be bit-perfect!!

The structures used to group data on a CD-ROM (the Yellow Book) are also derived from the Red Book. Like audio CDs (CD-DA), a CD-ROM sector contains 2,352 bytes of user data... To structure, address and protect this data, the CD-ROM standard further defines two sector modes, Mode 1 and Mode 2, which describe two different layouts for the data inside a sector.

Both Mode 1 and 2 sectors use the first 16 bytes for header information, but differ in the remaining 2,336 bytes due to the use of error correction bytes. Unlike an audio CD, a CD-ROM cannot rely on error concealment by interpolation; a higher reliability of the retrieved data is required. 

• Mode 1, used mostly for digital data, adds a 32-bit cyclic redundancy check (CRC) code for error detection, and a third layer of Reed–Solomon error correction leaving 2,048 bytes per sector available for data. 
• Mode 2, which is more appropriate for image or video data (where perfect reliability may be a little bit less important), contains no additional error detection or correction bytes, having therefore 2,336 available data bytes per sector. 

Note that both modes, like audio CDs, still benefit from the lower layers of error correction at the frame level.

Format	← 2,352 byte sector structure →
CD digital audio:	2,352 (Digital audio)
CD-ROM Mode 1:	12 (Sync pattern)	3 (Address)	1 (Mode, 0x01)	2,048 (Data)	4 (Error detection)	8 (Reserved, zero)	276 (Error correction)
CD-ROM Mode 2:	12 (Sync pattern)	3 (Address)	1 (Mode, 0x02)	2,336 (Data)

So I guess CD-DA is more liable to uncorrected errors, because nobody gives a toss about audio errors... 

Ripping programs can

• Read a sector multiple times and check they get the same result
• Use the "C2" feature implemented in many drives that allows the drive to report potential errors as guidance to the reading program

but of course, nothing can actually fix the errors if they can't be recovered, even if detected. Boo. Oh well. Off to eBay to source another CD-ROM drive...

New Ripping Software - Perfect Sound, Forever!! 

I've spent a lot of time trying to use XLD to rip my copies of Wagner's Ring to disk, and it's been very hard work. I don't know why these are so hard, but there are lots of errors, an they almost never match the AccurateRip database. So I thought I'd try dbpowerasp, the ripper produced by Spoon/Illuminate, the people who own the AccurateRip database. 

The software seems to work well in itself, it needs some adjusting in terms of tagging and filenames, but it it is taking an extraordinarily long time to rip the firstdisk. I started ripping last night, it read the first track, then announced it would retry 2000+ errors sectors. Great. I left it running when I went to bed... and when I came down this morning it was onto the 3rd track! It's 15.19, and it's still ripping the 4th, with 2676 frames to retry! The first track took 6.30 hours to rip, with its 2000 duff sectors. What is going on?! Are all my CDs going to be this hard? I reckon I should forget ripping CDs, and just play stuff off Tidal, because I can and life's too short!

Network Problems

Debugging the dodgy network... On the current running system (cheated on the systemd entry :-) ):

[root@Frontroom ~]# journalctl --output=short-iso | grep "eth0: carrier lost"

2017-02-22T18:35:43+0000 Frontroom systemd[1]: Time has been changed 

2017-02-24T04:35:42+0000 Frontroom dhcpcd[677]: eth0: carrier lost

2017-02-25T20:28:51+0000 Frontroom dhcpcd[677]: eth0: carrier lost

giving about 143,589 and 122,399 seconds between events. The lease is for 86400 seconds.

Annoyingly the Rune image clock starts on 22 Feb 2016, which is annoyingly close to the current date (25 Feb!). The --output=short-iso is required to display the year on the clock...

More data required... so I need to make the journal files non-volatile...

By default, the journal stores log data in /run/log/journal/. Since /run/ is volatile, log data is lost at reboot. To make the data persistent, it is sufficient to create /var/log/journal/ wheresystemd-journald will then store the data:

mkdir -p /var/log/journal
systemd-tmpfiles --create --prefix /var/log/journal

Tried that. Let's see if there are any more entries and if they survive a reboot!
I note that no entries have appeared in that directory yet... I wonder if I have to do something more?

Update: I edited /etc/systemd/journald.conf to change the Storage=volatile to Storage=persistent, then did systemctl restart systemd-journald.service to restart the logging with non-volatile storage. Hurrah - works!

Update:
The router log has the following entries around the time of the last outage (relevant bold):

[DHCP IP: (192.168.1.16)] to MAC address 00:BB:3A:33:62:DA, Saturday, Feb 25,2017 20:35:46
[DHCP IP: (192.168.1.3)] to MAC address B8:27:EB:25:C4:1A, Saturday, Feb 25,2017 20:28:53
[UPnP set event: Public_UPNP_C3] from source 192.168.1.11, Saturday, Feb 25,2017 20:25:28
[UPnP set event: Public_UPNP_C3] from source 192.168.1.11, Saturday, Feb 25,2017 20:10:27
[Time synchronized with NTP server] Saturday, Feb 25,2017 20:09:33
[Internet connected] IP address: 192.168.0.3, Saturday, Feb 25,2017 20:08:45
[UPnP set event: Public_UPNP_C3] from source 192.168.1.11, Saturday, Feb 25,2017 19:55:28
[UPnP set event: Public_UPNP_C3] from source 192.168.1.11, Saturday, Feb 25,2017 19:40:27
[Time synchronized with NTP server] Saturday, Feb 25,2017 19:38:43

That doesn't tell me a lot, but at least they agree! And there is no apparent fault with the router. I do note that my phone gets a lot of IP address assignments, at sub-10 minute intervals, which I notice. Maybe the signal is bad for that?

As an experiment, I might try plugging in the network extender I have and using that to provide a wired interface, to see if that makes a difference. The office RPi is using one of those and has no wired problem, although the wireless connection does fail a lot, despite using the wireless extender in the same room!!!

Update 2017-02-28:

Well, the link has been up now for 64 hours, without failing, using the Powerline network extender and a new, short Cat5 cable. This is positive. Maybe it's like my N years spent complaining about the laser printer's inadequacy and the uselessness of the drivers, when it was the cable all along...

Rune vs. Roon?

Up until now I've used Rune as the audio player on my Raspberry Pis. It's a cut-down ArchLinux using mpd as the player and a PHP-based web interface and control server to manage and configure the mpd and o/s.

It works ok most of the time. However, and maybe this is not a problem specific to Rune, it is fairly flakey in respect of network connectedness. Yeah, on startup it usually connects and exposes itself as host.local, connects to the server for ripped data, is ready to receive DLNA/uPnP streams and reports to interested parties like Linn Kazoo and Lumin on iOS.

It's hard to work out what's going on, because the problem is network connectivity, so beaming in on SSH is not possible, and a restart appears to kill the log files - I need to research this a bit more. The log shows outage of the wired connection, which is weird... These entries show it's down for around 1 second! What's going on?

Feb 25 20:28:51 Frontroom kernel: smsc95xx 1-1.1:1.0 eth0: link down

Feb 25 20:28:51 Frontroom dhcpcd[677]: eth0: carrier lost

Feb 25 20:28:51 Frontroom dhcpcd[677]: eth0: deleting route to 192.168.1.0/24

Feb 25 20:28:51 Frontroom dhcpcd[677]: eth0: deleting default route via 192.168.1.1

Feb 25 20:28:51 Frontroom avahi-daemon[275]: Withdrawing address record for 192.168.1.3 on eth0.

Feb 25 20:28:51 Frontroom avahi-daemon[275]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.3.

Feb 25 20:28:51 Frontroom avahi-daemon[275]: Interface eth0.IPv4 no longer relevant for mDNS.

Feb 25 20:28:52 Frontroom ifplugd[280]: Link beat lost.

Feb 25 20:28:52 Frontroom dhcpcd[677]: eth0: carrier acquired

Feb 25 20:28:52 Frontroom kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x45E1

Feb 25 20:28:52 Frontroom dhcpcd[677]: eth0: IAID eb:25:c4:1a

Feb 25 20:28:53 Frontroom dhcpcd[677]: eth0: rebinding lease of 192.168.1.3

Feb 25 20:28:53 Frontroom dhcpcd[677]: eth0: probing address 192.168.1.3/24

Feb 25 20:28:53 Frontroom ifplugd[280]: Link beat detected.

Feb 25 20:28:54 Frontroom ntpd[348]: Deleting interface #5 eth0, 192.168.1.3#123, interface stats: received=73, sent=75, dropped

Feb 25 20:28:54 Frontroom ntpd[348]: 178.79.160.57 local addr 192.168.1.3 -> <null>

Feb 25 20:28:57 Frontroom dhcpcd[677]: eth0: leased 192.168.1.3 for 86400 seconds

Feb 25 20:28:57 Frontroom avahi-daemon[275]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.3.

Feb 25 20:28:57 Frontroom avahi-daemon[275]: New relevant interface eth0.IPv4 for mDNS.

Feb 25 20:28:57 Frontroom avahi-daemon[275]: Registering new address record for 192.168.1.3 on eth0.IPv4.

Feb 25 20:28:57 Frontroom dhcpcd[677]: eth0: adding route to 192.168.1.0/24

Feb 25 20:28:57 Frontroom dhcpcd[677]: eth0: adding default route via 192.168.1.1

Feb 25 20:28:57 Frontroom dhcpcd[677]: eth0: removing route to 192.168.1.0/24

Feb 25 20:28:59 Frontroom ntpd[348]: Listen normally on 6 eth0 192.168.1.3:123

Feb 25 20:28:59 Frontroom ntpd[348]: 178.79.160.57 local addr 192.168.1.12 -> 192.168.1.3

Feb 25 20:28:59 Frontroom ntpd[348]: new interface(s) found: waking up resolver

Anyway, I've been investigating Roon, which I first encountered at Keith's house when I heard the Kii Audio Threes. He's running a MacMini as the Roon Core, the Rune Control on an iPad and using the Mac Mini as a Roon Output. it all seems very well thought through, and pretty robust. The one drawback is that it costs money, continuing money, at $120/year or $500 lifetime! It does have a fantastic interface, some amazing metadata capabilities and it also interfaces utterly seamlessly with Tidal. I'd have to provide a sensibly powerful box for the Core, I suspect an RPi isn't going to cut it, in fact, the Roon doco explicitly says it won't. 

But all this is moot if my hub is letting me down - how do I debug the network interface??

A Video Sidetrack

I have a spare USB cam, a new RPi 3 B and a boiler in the loft that I want to monitor the front panel of without constantly going upstairs, climbing the ladder and hoiking myself into the roof. Clearly a webcam is the answer!

I tried using ssh & X to connect remotely and view the camera in real-time, but it seems to have problems of one sort or another. The whole thing works fine when using the HDMI output, but not so well over X. I tried using cheese, but that doesn't work over X (bug!) and VLC - that struggles too, it can't find any useful OpenGL renderers for X. So I'm about to try UV4L from http://www.linux-projects.org/uv4l/installation/, which appears to offer live streaming options. Hurray!

Using .local DNS names

Up until now,  the Rune installations (based on ArchLinux) haven't been able to use the Bonjour .local domain to do lookups. They broadcast their own hostnames, so they can be seen from other places, but they can't see each other or the server. Boring.

How do you fix this?? Answer here...

Install nss-mdns:

pacman -S nss-mdns

Tell C libs to use mDNS:

vi /etc/nsswitch.conf

Add the value mdns_minimal [NOTFOUND=return] in the hosts line...

Then it works!

I think I should tell Frank on the Rune forum about this...

Rune Audio, RPi and networking recovery

It seems that if the wireless/wired router is rebooted, then all the Rune Audio instances have to be restarted to link up with the wired interface (and possibly the wireless). If this is true, this is very boring. It certainly seems to be true - I have to reboot the router sometimes because it gets upset and won't connect my phone (1st world problems eh??).

So I'm looking at the networking setup in Rune - here's the Rune debug first few lines:

###### System info ######
Linux version 4.1.20-1-ARCH (builduser@leming) (gcc version 5.3.0 (GCC) ) #1 SMP Sat Mar 19 20:07:23 MDT 2016

system time: Tue Nov 22 15:54:10 GMT 2016

system load: 0.19 0.10 0.06 1/181 3960

HW platform: RaspberryPi2 (08)

playerID: 08b26fff2ac4ddac6fee7fbbc1890504ae

I'm using the Office system, because that's the one I have configured with

• A wired connection through an Airport Express, so it's actually wireless but looks like a wired connection to the RPi
• A wireless connection to the Netgear router

You can see these here:

[root@office ~]# ifconfig

eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

        inet 192.168.1.12  netmask 255.255.255.0  broadcast 192.168.1.255

        ether b8:27:eb:d3:a9:ca  txqueuelen 1000  (Ethernet)

        RX packets 747196  bytes 156859854 (149.5 MiB)

        RX errors 0  dropped 8  overruns 0  frame 0

        TX packets 573333  bytes 203126147 (193.7 MiB)

        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

        inet 192.168.1.14  netmask 255.255.255.0  broadcast 192.168.1.255

        ether b8:27:eb:86:fc:9f  txqueuelen 1000  (Ethernet)

        RX packets 31182  bytes 3441166 (3.2 MiB)

        RX errors 0  dropped 3566  overruns 0  frame 0

        TX packets 2181  bytes 412069 (402.4 KiB)

        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

I can't see them properly in the router - it appears to be a bit confused (maybe it's the fricking router that's the problem...) - here's the devices connected

Wired Devices

#	IP Address	Device Name	MAC Address
1	192.168.1.3	server	B8:27:EB:15:6E:B7
2	192.168.1.4	Frontroom	B8:27:EB:25:C4:1A
3	192.168.1.11	FRONTROOM	B8:27:EB:25:C4:1A

 Wireless Devices (Wireless intruders also show up here)

#	IP Address	Device Name	MAC Address
1	192.168.1.12	office	B8:27:EB:D3:A9:CA
2	192.168.1.2	johns-airport-express	00:1F:F3:07:9F:EB
3	--	--	B8:27:EB:86:FC:9F
4	192.168.1.13	meye-55ace5a8	00:0F:60:06:7E:10
5	--	--	B8:27:EB:70:91:4F
6	192.168.1.10	meye-e5167b33	74:DA:38:3A:33:7C
7	192.168.1.7	Macintosh-Gouk	D8:A2:5E:97:E7:E6
8	192.168.1.6	Jenny-PC	1C:65:9D:48:E0:77
9	--	--	F0:DB:F8:69:8E:97

Obviously, 192.168.1.12 is the wired connection (eth0), it shows up here because it's via the Airport Express (192.168.1.2). The wireless connection (wlan0) is actually at 192.168.1.14, on B8:27:EB:86:FC:9F - I know because I can telnet into it!! Weird. The router is shyte, really!!

Anyway, I have been testing the unplug/replug of the wired connection, and the unplug/replug of the Airport Express, thereby simulating the two different situations with the usual router. It's hard to do this for real because if I unplug the router I lose connectivity to the RPi. I guess I could look at the logs after the fact, if they survive a reboot, I think they do.

Commands Used

Rune uses ArchLinux. The commands I'm using to investigate the networking activity are:

• journalctl - enables listing of the system journal. Use -f to tail the journal
• message <your message> - sends a message to the system journal, very handy for documenting equipment state changes in the log alongside the system's reaction to them
• systemctl - useful for listing the running services etc.

Results

Interesting! The first time I did it, the eth0 interface didn't seem to reconnect (highlighted time a result of search hit on "15:40"!); irrelevant entries deleted:

Cable unplugged

Nov 22 15:40:08 office dhcpcd[1057]: eth0: carrier lost

Nov 22 15:40:08 office kernel: smsc95xx 1-1.1:1.0 eth0: link down

Nov 22 15:40:09 office dhcpcd[1057]: eth0: deleting route to 192.168.1.0/24

Nov 22 15:40:09 office dhcpcd[1057]: eth0: deleting default route via 192.168.1.1

Nov 22 15:40:09 office ifplugd[224]: Link beat lost.

Nov 22 15:40:15 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 down'.

Nov 22 15:40:15 office ifplugd[224]: client: Stopping network profile 'eth0'...

Nov 22 15:40:15 office dhcpcd[474]: sending signal TERM to pid 1057

Nov 22 15:40:15 office dhcpcd[474]: waiting for pid 1057 to exit

Nov 22 15:40:15 office dhcpcd[1057]: received SIGTERM, stopping

Nov 22 15:40:15 office dhcpcd[1057]: eth0: removing interface

Nov 22 15:40:15 office dhcpcd[1057]: dhcpcd exited

Nov 22 15:40:15 office ifplugd[224]: client: Stopped network profile 'eth0'

Nov 22 15:40:15 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 15:40:15 office ifplugd[224]: Program executed successfully.

Nov 22 15:40:15 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Cable replugged

Nov 22 15:40:25 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x45E1

Nov 22 15:40:25 office ifplugd[224]: Link beat detected.

Nov 22 15:40:26 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 up'.

Nov 22 15:40:26 office ifplugd[224]: client: Starting network profile 'eth0'...

Nov 22 15:40:26 office dhcpcd[511]: DUID 00:01:00:01:1c:72:2b:ea:06:92:c5:a0:0d:d6

Nov 22 15:40:26 office dhcpcd[511]: eth0: IAID eb:d3:a9:ca

Nov 22 15:40:26 office dhcpcd[511]: eth0: rebinding lease of 192.168.1.12

Nov 22 15:40:31 office dhcpcd[511]: eth0: NAK: from 192.168.1.1

Nov 22 15:40:31 office dhcpcd[511]: eth0: soliciting a DHCP lease

Nov 22 15:40:32 office dhcpcd[511]: eth0: offered 192.168.1.12 from 192.168.1.1

Nov 22 15:40:32 office dhcpcd[511]: eth0: probing address 192.168.1.12/24

Nov 22 15:40:37 office dhcpcd[511]: eth0: leased 192.168.1.12 for 86400 seconds

Nov 22 15:40:37 office dhcpcd[511]: eth0: adding route to 192.168.1.0/24

Nov 22 15:40:37 office dhcpcd[511]: eth0: adding default route via 192.168.1.1

Nov 22 15:40:37 office dhcpcd[511]: forked to background, child pid 582

Nov 22 15:40:37 office ifplugd[224]: client: Started network profile 'eth0'

Nov 22 15:40:37 office ifplugd[224]: Program executed successfully.

Router unplugged

Nov 22 15:41:03 office dhcpcd[582]: eth0: carrier lost

Nov 22 15:41:03 office kernel: smsc95xx 1-1.1:1.0 eth0: link down

Nov 22 15:41:03 office ifplugd[224]: Link beat lost.

Nov 22 15:41:03 office dhcpcd[582]: eth0: deleting route to 192.168.1.0/24

Nov 22 15:41:03 office dhcpcd[582]: eth0: deleting default route via 192.168.1.1

Nov 22 15:41:09 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 down'.

Nov 22 15:41:09 office ifplugd[224]: client: Stopping network profile 'eth0'...

Nov 22 15:41:09 office dhcpcd[653]: sending signal TERM to pid 582

Nov 22 15:41:09 office dhcpcd[653]: waiting for pid 582 to exit

Nov 22 15:41:09 office dhcpcd[582]: received SIGTERM, stopping

Nov 22 15:41:09 office dhcpcd[582]: eth0: removing interface

Nov 22 15:41:09 office dhcpcd[582]: dhcpcd exited

Nov 22 15:41:09 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 15:41:09 office ifplugd[224]: client: Stopped network profile 'eth0'

Nov 22 15:41:10 office ifplugd[224]: Program executed successfully.

Nov 22 15:41:10 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 15:42:03 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 10Mbps, half-duplex, lpa 0x0020

Router replugged

Nov 22 15:42:04 office ifplugd[224]: Link beat detected.

Nov 22 15:42:05 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 up'.

Nov 22 15:42:05 office ifplugd[224]: client: Starting network profile 'eth0'...

Nov 22 15:42:05 office dhcpcd[707]: DUID 00:01:00:01:1c:72:2b:ea:06:92:c5:a0:0d:d6

Nov 22 15:42:05 office dhcpcd[707]: eth0: IAID eb:d3:a9:ca

Nov 22 15:42:05 office dhcpcd[707]: eth0: rebinding lease of 192.168.1.12

Nov 22 15:42:10 office dhcpcd[707]: eth0: DHCP lease expired

Nov 22 15:42:10 office dhcpcd[707]: eth0: soliciting a DHCP lease

Nov 22 15:42:18 office dhcpcd[707]: eth0: carrier lost

Nov 22 15:42:18 office kernel: smsc95xx 1-1.1:1.0 eth0: link down

Nov 22 15:42:20 office dhcpcd[707]: eth0: carrier acquired

Nov 22 15:42:20 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x45E1

Nov 22 15:42:21 office dhcpcd[707]: eth0: IAID eb:d3:a9:ca

Nov 22 15:42:21 office dhcpcd[707]: eth0: soliciting a DHCP lease

Nov 22 15:42:35 office dhcpcd[707]: timed out

Nov 22 15:42:35 office dhcpcd[707]: dhcpcd exited

Nov 22 15:42:35 office ifplugd[224]: client: <3>DHCP IPv4 lease attempt failed on interface 'eth0'

Nov 22 15:42:35 office ifplugd[224]: client: <3>Failed to bring the network up for profile 'eth0'

Nov 22 15:42:35 office ifplugd[224]: client: <3>Could not start any suitable profile

Nov 22 15:42:35 office ifplugd[224]: Program execution failed, return value is 1.

Nov 22 15:42:35 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 15:42:35 office ifplugd[224]: Link beat lost.

Nov 22 15:42:35 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 15:42:37 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x45E1

Nov 22 15:42:37 office ifplugd[224]: Link beat detected.

At this point, ifconfig was not showing any IP address associated with eth0, although it was shown as "running"... So I invoked netctl stop/start eth0... Maybe I should have waited longer?

Nov 22 15:45:59 office systemd[1]: Stopped Networking for netctl profile eth0.

Nov 22 15:46:08 office systemd[1]: Created slice system-netctl.slice.

Nov 22 15:46:08 office systemd[1]: Starting Networking for netctl profile eth0...

Nov 22 15:46:08 office network[917]: Starting network profile 'eth0'...

Nov 22 15:46:08 office dhcpcd[922]: DUID 00:01:00:01:1c:72:2b:ea:06:92:c5:a0:0d:d6

Nov 22 15:46:08 office dhcpcd[922]: eth0: IAID eb:d3:a9:ca

Nov 22 15:46:09 office dhcpcd[922]: eth0: soliciting a DHCP lease

Nov 22 15:46:14 office dhcpcd[922]: eth0: offered 192.168.1.12 from 192.168.1.1

Nov 22 15:46:14 office dhcpcd[922]: eth0: probing address 192.168.1.12/24

Nov 22 15:46:18 office dhcpcd[922]: eth0: leased 192.168.1.12 for 86400 seconds

Nov 22 15:46:18 office dhcpcd[922]: eth0: adding route to 192.168.1.0/24

Nov 22 15:46:18 office dhcpcd[922]: eth0: adding default route via 192.168.1.1

Nov 22 15:46:19 office dhcpcd[922]: forked to background, child pid 969

Nov 22 15:46:19 office network[917]: Started network profile 'eth0'

Nov 22 15:46:19 office systemd[1]: Started Networking for netctl profile eth0.

And after that it was running ok. But I had intervened...

So time for a better documented test. I switched wlan0 to the normal router (192.1.68.1.xxx) first, otherwise I couldn't talk to it properly.

Nov 22 16:02:05 office root[4543]: +++++++ Cable unplugged

Nov 22 16:02:31 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:02:31 office kernel: smsc95xx 1-1.1:1.0 eth0: link down

Nov 22 16:02:31 office dhcpcd[969]: eth0: deleting route to 192.168.1.0/24

Nov 22 16:02:31 office dhcpcd[969]: eth0: deleting default route via 192.168.1.1

Nov 22 16:02:32 office ifplugd[224]: Link beat lost.

Nov 22 16:02:33 office ntpd[284]: Deleting interface #6 eth0, 192.168.1.12#123, interface stats: received=9, sent=10, dropped=0, active_time=973 secs

Nov 22 16:02:38 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 down'.

Nov 22 16:02:38 office ifplugd[224]: Program execution failed, return value is 1.

Nov 22 16:02:59 office root[4612]: +++++++ Cable replugged

Nov 22 16:03:04 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:03:04 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x45E1

Nov 22 16:03:04 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:03:04 office ifplugd[224]: Link beat detected.

Nov 22 16:03:04 office dhcpcd[969]: eth0: rebinding lease of 192.168.1.12

Nov 22 16:03:05 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 up'.

Nov 22 16:03:05 office ifplugd[224]: client: Starting network profile 'eth0'...

Nov 22 16:03:05 office dhcpcd[4633]: dhcpcd already running on pid 969 (/run/dhcpcd-eth0-4.pid)

Nov 22 16:03:05 office ifplugd[224]: client: <3>DHCP IPv4 lease attempt failed on interface 'eth0'

Nov 22 16:03:05 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:03:05 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 16:03:05 office ifplugd[224]: client: <3>Failed to bring the network up for profile 'eth0'

Nov 22 16:03:05 office ifplugd[224]: client: <3>Could not start any suitable profile

Nov 22 16:03:05 office ifplugd[224]: Program execution failed, return value is 1.

Nov 22 16:03:05 office ifplugd[224]: Link beat lost.

Nov 22 16:03:05 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 16:03:05 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:03:05 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:03:05 office dhcpcd[969]: eth0: rebinding lease of 192.168.1.12

Nov 22 16:03:07 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x45E1

Nov 22 16:03:07 office ifplugd[224]: Link beat detected.

Nov 22 16:03:10 office dhcpcd[969]: eth0: DHCP lease expired

Nov 22 16:03:10 office dhcpcd[969]: eth0: soliciting a DHCP lease

Nov 22 16:03:15 office dhcpcd[969]: eth0: offered 192.168.1.12 from 192.168.1.1

Nov 22 16:03:15 office dhcpcd[969]: eth0: probing address 192.168.1.12/24

Nov 22 16:03:19 office dhcpcd[969]: eth0: leased 192.168.1.12 for 86400 seconds

Nov 22 16:03:19 office dhcpcd[969]: eth0: adding route to 192.168.1.0/24

Nov 22 16:03:19 office dhcpcd[969]: eth0: adding default route via 192.168.1.1

Nov 22 16:03:19 office dhcpcd[969]: eth0: removing route to 192.168.1.0/24

Looks like the cable un/replug works like last time... Try the router

Nov 22 16:06:05 office root[4784]: +++++++ Router unplugged

Nov 22 16:06:11 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:06:11 office kernel: smsc95xx 1-1.1:1.0 eth0: link down

Nov 22 16:06:11 office dhcpcd[969]: eth0: deleting default route via 192.168.1.1

Nov 22 16:06:11 office avahi-daemon[221]: Withdrawing address record for 192.168.1.12 on eth0.

Nov 22 16:06:11 office avahi-daemon[221]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.12.

Nov 22 16:06:11 office avahi-daemon[221]: Interface eth0.IPv4 no longer relevant for mDNS.

Nov 22 16:06:11 office ifplugd[224]: Link beat lost.

Nov 22 16:06:13 office ntpd[284]: Deleting interface #9 eth0, 192.168.1.12#123, interface stats: received=0, sent=0, dropped=0, active_time=172 secs

Nov 22 16:06:17 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 down'.

Nov 22 16:06:17 office ifplugd[224]: Program execution failed, return value is 1.

Nov 22 16:07:25 office root[4866]: +++++++ Router replugged

Nov 22 16:08:08 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:08:08 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 10Mbps, half-duplex, lpa 0x0020

Nov 22 16:08:09 office ifplugd[224]: Link beat detected.

Nov 22 16:08:09 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:08:09 office dhcpcd[969]: eth0: rebinding lease of 192.168.1.12

Nov 22 16:08:10 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 up'.

Nov 22 16:08:10 office ifplugd[224]: client: Starting network profile 'eth0'...

Nov 22 16:08:10 office dhcpcd[4911]: dhcpcd already running on pid 969 (/run/dhcpcd-eth0-4.pid)

Nov 22 16:08:10 office ifplugd[224]: client: <3>DHCP IPv4 lease attempt failed on interface 'eth0'

Nov 22 16:08:10 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:08:10 office ifplugd[224]: client: <3>Failed to bring the network up for profile 'eth0'

Nov 22 16:08:10 office ifplugd[224]: client: <3>Could not start any suitable profile

Nov 22 16:08:10 office ifplugd[224]: Program execution failed, return value is 1.

Nov 22 16:08:10 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 16:08:10 office ifplugd[224]: Link beat lost.

Nov 22 16:08:10 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 16:08:10 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:08:10 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:08:10 office dhcpcd[969]: eth0: rebinding lease of 192.168.1.12

Nov 22 16:08:12 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 10Mbps, half-duplex, lpa 0x0020

Nov 22 16:08:13 office ifplugd[224]: Link beat detected.

Nov 22 16:08:15 office dhcpcd[969]: eth0: DHCP lease expired

Nov 22 16:08:15 office dhcpcd[969]: eth0: soliciting a DHCP lease

Nov 22 16:08:23 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:08:23 office kernel: smsc95xx 1-1.1:1.0 eth0: link down

Nov 22 16:08:24 office ifplugd[224]: Link beat lost.

Nov 22 16:08:26 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:08:26 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lap 0x45E1
Nov 22 16:08:26 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:08:26 office dhcpcd[969]: eth0: soliciting a DHCP lease

Nov 22 16:08:27 office ifplugd[224]: Link beat detected.

Nov 22 16:08:54 office dhcpcd[969]: eth0: offered 192.168.1.12 from 192.168.1.1

Nov 22 16:08:54 office dhcpcd[969]: eth0: probing address 192.168.1.12/24

Nov 22 16:08:59 office dhcpcd[969]: eth0: leased 192.168.1.12 for 86400 seconds

Nov 22 16:08:59 office dhcpcd[969]: eth0: adding route to 192.168.1.0/24

Nov 22 16:08:59 office dhcpcd[969]: eth0: adding default route via 192.168.1.1

Nov 22 16:08:59 office dhcpcd[969]: eth0: removing route to 192.168.1.0/24

Nov 22 16:13:41 office root[5157]: +++++++ Router unplugged

Nov 22 16:13:48 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:13:48 office kernel: smsc95xx 1-1.1:1.0 eth0: link down

Nov 22 16:13:48 office dhcpcd[969]: eth0: deleting default route via 192.168.1.1

Nov 22 16:13:48 office ifplugd[224]: Link beat lost.

Nov 22 16:13:54 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 down'.

Nov 22 16:13:54 office ifplugd[224]: Program execution failed, return value is 1.

Nov 22 16:14:30 office root[5224]: +++++++ Router replugged

Nov 22 16:15:16 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:15:16 office ifplugd[224]: Link beat detected.

Nov 22 16:15:16 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 10Mbps, half-duplex, lpa 0x0020

Nov 22 16:15:16 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:15:17 office dhcpcd[969]: eth0: rebinding lease of 192.168.1.12

Nov 22 16:15:17 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 up'.

Nov 22 16:15:17 office ifplugd[224]: client: Starting network profile 'eth0'...

Nov 22 16:15:17 office dhcpcd[5261]: dhcpcd already running on pid 969 (/run/dhcpcd-eth0-4.pid)

Nov 22 16:15:17 office ifplugd[224]: client: <3>DHCP IPv4 lease attempt failed on interface 'eth0'

Nov 22 16:15:17 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:15:17 office ifplugd[224]: client: <3>Failed to bring the network up for profile 'eth0'

Nov 22 16:15:17 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 16:15:17 office ifplugd[224]: client: <3>Could not start any suitable profile

Nov 22 16:15:17 office ifplugd[224]: Program execution failed, return value is 1.

Nov 22 16:15:18 office ifplugd[224]: Link beat lost.

Nov 22 16:15:18 office kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup

Nov 22 16:15:18 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:15:18 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:15:18 office dhcpcd[969]: eth0: rebinding lease of 192.168.1.12

Nov 22 16:15:20 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 10Mbps, half-duplex, lap 0x0020

Nov 22 16:15:21 office ifplugd[224]: Link beat detected.Nov 22 16:15:23 office dhcpcd[969]: eth0: DHCP lease expired

Nov 22 16:15:23 office dhcpcd[969]: eth0: soliciting a DHCP lease

Nov 22 16:15:31 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:15:31 office kernel: smsc95xx 1-1.1:1.0 eth0: link down

Nov 22 16:15:32 office ifplugd[224]: Link beat lost.

Nov 22 16:15:34 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:15:34 office kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x45E1

Nov 22 16:15:34 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:15:34 office dhcpcd[969]: eth0: soliciting a DHCP lease

Nov 22 16:15:35 office ifplugd[224]: Link beat detected.

Nov 22 16:15:46 office dhcpcd[969]: eth0: offered 192.168.1.12 from 192.168.1.1

Nov 22 16:15:46 office dhcpcd[969]: eth0: probing address 192.168.1.12/24

Nov 22 16:15:51 office dhcpcd[969]: eth0: leased 192.168.1.12 for 86400 seconds

Nov 22 16:15:51 office dhcpcd[969]: eth0: adding route to 192.168.1.0/24

Nov 22 16:15:51 office dhcpcd[969]: eth0: adding default route via 192.168.1.1

Nov 22 16:15:51 office dhcpcd[969]: eth0: removing route to 192.168.1.0/24

Hmm. The main difference between the initial (failed) attempt and the (successful) subsequent attempts is that in the latter case the ifplugd daemon fails to stop the related dhcpcd instance, so it presumably keeps going and then eventually acquires an IP address. So why doesn't that work in the former case?? Aha...

Nov 22 15:42:35 office dhcpcd[707]: timed out

That's what happens - at that point, the dhcpcd stops, and is not restarted. I wonder if I can tweak the timeout??

Let's see what systemctl says...

[root@office etc]# systemctl status netctl@eth0.service

● netctl@eth0.service - Networking for netctl profile eth0

   Loaded: loaded (/usr/lib/systemd/system/netctl@.service; static; vendor preset: disabled)

   Active: active (exited) since Tue 2016-11-22 15:46:19 GMT; 4h 2min ago

     Docs: man:netctl.profile(5)

 Main PID: 917 (code=exited, status=0/SUCCESS)

   CGroup: /system.slice/system-netctl.slice/netctl@eth0.service

           └─969 dhcpcd -4 -q -t 30 -L eth0

Nov 22 16:15:31 office dhcpcd[969]: eth0: carrier lost

Nov 22 16:15:34 office dhcpcd[969]: eth0: carrier acquired

Nov 22 16:15:34 office dhcpcd[969]: eth0: IAID eb:d3:a9:ca

Nov 22 16:15:34 office dhcpcd[969]: eth0: soliciting a DHCP lease

Nov 22 16:15:46 office dhcpcd[969]: eth0: offered 192.168.1.12 from 192.168.1.1

Nov 22 16:15:46 office dhcpcd[969]: eth0: probing address 192.168.1.12/24

Nov 22 16:15:51 office dhcpcd[969]: eth0: leased 192.168.1.12 for 86400 seconds

Nov 22 16:15:51 office dhcpcd[969]: eth0: adding route to 192.168.1.0/24

Nov 22 16:15:51 office dhcpcd[969]: eth0: adding default route via 192.168.1.1

Nov 22 16:15:51 office dhcpcd[969]: eth0: removing route to 192.168.1.0/24

Looks like it gets started here:

Feb 22 14:40:20 office ifplugd[224]: Executing '/etc/ifplugd/netctl.action eth0 up'.

Feb 22 14:40:20 office ifplugd[224]: client: Starting network profile 'eth0'...

Feb 22 14:40:20 office dhcpcd[383]: DUID 00:01:00:01:1c:72:2b:ea:06:92:c5:a0:0d:d6

Feb 22 14:40:20 office dhcpcd[383]: eth0: IAID eb:d3:a9:ca

ArchLinux uses systemd, not init!!

/etc/ifplugd/netctl.action ->

    $1 = etho
    $2 = up

  . /usr/lib/network/globals

    {PROFILE_DIR="/etc/netctl"

    {SUBR_DIR="/usr/lib/network"

    {STATE_DIR="/run/network"

    {STATE_FILE="${NETCTL_STATE_FILE:-/var/lib/netctl/netctl.state}"

    PROFILE_FILE="/run/network/ifplugd_eth0.profile"

  case "up" in

    up)

      while read -r profile; do

          if ForceConnect=yes "/usr/lib/network/network" start "eth0"; then

              mkdir -p "$(dirname "/run/network/ifplugd_eth0.profile")"

              printf "%s" "$profile" > "/run/network/ifplugd_eth0.profile"

              exit 0

          fi

      done < <(list_profiles | while read -r profile; do

          report_debug "Examining profile 'eth0'"

          (

            source "/etc/netctl/eth0" > /dev/null

which has 

    Description='eth0 connection'

    Interface=eth0

    ForceConnect=yes

    SkipNoCarrier=yes

    Connection=ethernet

    IP=dhcp

So - no obvious clues there... let's look at the referenced SUBR file /usr/lib/network/network:

$1 = start
$2 = eth0

# Expose the profile name

Profile=eth0

load_profile "$Profile"

which translates to

## Sources all hooks, a profile and any interface hook

# $1: profile name

load_profile() {

    local hook

    if [[ ! -r "/etc/netctl/etho" ]]; then

        exit_error "Profile 'eth0' does not exist or is not readable"

    fi
...

    source "/etc/netctl/$1"

    if [[ -z eth0 ]]; then

        exit_error "Profile 'eth0' does not specify an interface"

    fi

    if [[ ! -r "${ethernet:+/usr/lib/network/connections/ethernet}" ]]; then

        exit_error "Profile 'eth0' does not specify a valid connection"

    fi

    if [[ -x "$PROFILE_DIR/interfaces/eth0" ]]; then

        source "$PROFILE_DIR/interfaces/eth0"

    fi

    source "/usr/lib/network/connections/ethernet"

which contains

. "/usr/lib/network/ip" - contains some DHCP-invoking code!!

which we want to end up with a result like
dhcpcd -4 -q -t 30 -L eth0

dhcp_call "${DHCPClient:-dhcpcd}" start 4

## Interface a DHCP client

# $1: DHCP client - dhcpcd

# $2: command     - start

# $3...: additional arguments - 4

dhcp_call() {

    local client="dhcpcd" command="start"

    shift 2

    if [[ ! -r "/usr/lib/network/dhcp/dhcpcd" ]]; then

        report_error "DHCP client 'dhcpcd' is unsupported"

        return 127

    fi

    if ! source "/usr/lib/network/dhcp/dhcpcd"; then

        report_error "DHCP client 'dhcpcd' is not installed or not ready"

        return 127

    fi

    "dhcpcd_start" "4"

}

The file /usr/lib/network/dhcp/dhcpcd contains:

dhcpcd_start() {

    local options

    case $1 in

      4) options="$DhcpcdOptions -L";; - guess we're going for IP4!

      6) options=$DhcpcdOptions6;;

      *) return 1;;

    esac

    if [[ $2 == "noaddr" ]]; then

        report_error "Using 'dhcpcd' for configuration without address assignment is unsupported"

        return 1

    fi

    # If using own dns, tell dhcpcd to NOT replace resolv.conf

    [[ $DNS ]] && options+=" -C resolv.conf"

    if ! do_debug do_readable dhcpcd -$1 -q -t "${TimeoutDHCP:-30}" $options "$Interface"; then

        report_error "DHCP IPv$1 lease attempt failed on interface '$Interface'"

        return 1

    fi

}

Added a line to /etc/netctl/eth0:

TimeoutDHCP=60

Let's see if that does the trick! It's also suggested in https://www.raspberrypi.org/forums/viewtopic.php?f=28&t=46348

ethernet_up() {

    if ! is_interface "$Interface"; then

        report_error "Interface '$Interface' does not exist"

        return 1

    fi

    # Disable IPv6 before bringing the interface up to prevent SLAAC

    if [[ $IP6 == "no" ]]; then

        sysctl -q -w "net.ipv6.conf.${Interface/.//}.disable_ipv6=1"

    fi

    if ! bring_interface_up "$Interface"; then

        report_error "Failed to bring interface '$Interface' up"

        return 1

    fi

    if is_yes "${SkipNoCarrier:-no}"; then

        SkipDAD=yes

    else

        # Some cards are plain slow to come up. Don't fail immediately.

        if ! timeout_wait "${TimeoutCarrier:-5}" '(( $(< "/sys/class/net/$Interface/carrier") ))'; then

            report_error "No connection found on interface '$Interface' (timeout)"

            bring_interface_down "$Interface"

            return 1

        fi

    fi

...

}