search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.19k stars 570 forks source link

Very slight popping noise on high end system #459

Closed x187lockdown closed 4 years ago

x187lockdown commented 7 years ago

Hi Mike,

I have the following setup:

Raspberry PI 2B+ (Rasbian, TP Link Dual band Wifi) Hifiberry DIGI+ Audiolab MDAC+ Naim Nait 5SI DynAudio Emit M20s

I'm using the optical out from the DIGI+ which feeds the Audiolab MDAC+. The system itself sounds superb, I get the very occasional dropout from Airplay but it's no issue, the issues lies in a very small an just about noticeable popping/cackling/tearing sound on some tracks. Sounds very slightly like a blown tweeter. Now I know it's not the system or the source (Tidal) as using a USB cable straight into the MDAC+ from a laptop works flawlessly, but I have no idea where to start where this problem could be arising from. It's more noticeable on AKG reference headphones

I wondered if this was something you've come across before and if you could maybe recommend some settings I could tweak to see if it cures this issue? My version of Shairport-sync is no more than a few months old. I'm not at home right now but if needed I can post the specific versions of everything if nothing obvious springs to mind.

Many thanks, Mike

mikebrady commented 7 years ago

Thanks for the post. What interpolation settings are you using?

x187lockdown commented 7 years ago

I went for soxr. Is the Rasberry PI capable of this as I just noticed in your readme you say you need a reasonably fast processor

mikebrady commented 7 years ago

Thanks. Yep, soxr is right, and the Pi is able to deal with it. Okay, the next thing would be to turn on statistics so that we can get an idea of how much interpolation and, possibly, packet loss is going on. If you could look in the log using sudo journalctl -n 1000 say, and post the statistics entries for maybe 10 minutes, it would be useful.

x187lockdown commented 7 years ago

Excuse the delay in replying. I did a restart of the Rasberry Pi and then played an album via Airplay, I heard the issue during this session. It's not the sound of anything dropping out, it's more like a slightly blown speaker. You can hear it on tracks where it's just a vocal and a piano and it seems to when the music gets louder rather than random interference.

Let me know of any other logs that you might find useful. Thanks

sudo journalctl -n 1000
-- Logs begin at Tue 2017-01-17 22:17:01 UTC, end at Wed 2017-01-18 01:22:22 UTC. --
Jan 17 22:17:01 raspberrypi systemd-journal[106]: Runtime journal is using 5.7M (max allowed 46.2M, trying to leave 69.4M free of 456.9M available → current limit 46.2M).
Jan 17 22:17:01 raspberrypi systemd-journal[106]: Runtime journal is using 5.7M (max allowed 46.2M, trying to leave 69.4M free of 456.9M available → current limit 46.2M).
Jan 17 22:17:01 raspberrypi kernel: Booting Linux on physical CPU 0xf00
Jan 17 22:17:01 raspberrypi kernel: Initializing cgroup subsys cpuset
Jan 17 22:17:01 raspberrypi kernel: Initializing cgroup subsys cpu
Jan 17 22:17:01 raspberrypi kernel: Initializing cgroup subsys cpuacct
Jan 17 22:17:01 raspberrypi kernel: Linux version 4.1.19-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #853 SMP Wed Mar 9 18:09:16 GMT 2016
Jan 17 22:17:01 raspberrypi kernel: CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
Jan 17 22:17:01 raspberrypi kernel: CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Jan 17 22:17:01 raspberrypi kernel: Machine model: Raspberry Pi 2 Model B Rev 1.1
Jan 17 22:17:01 raspberrypi kernel: cma: Reserved 8 MiB at 0x3a400000
Jan 17 22:17:01 raspberrypi kernel: Memory policy: Data cache writealloc
Jan 17 22:17:01 raspberrypi kernel: On node 0 totalpages: 241664
Jan 17 22:17:01 raspberrypi kernel: free_area_init_node: node 0, pgdat 80880fc0, node_mem_map b9bb4000
Jan 17 22:17:01 raspberrypi kernel:   Normal zone: 2124 pages used for memmap
Jan 17 22:17:01 raspberrypi kernel:   Normal zone: 0 pages reserved
Jan 17 22:17:01 raspberrypi kernel:   Normal zone: 241664 pages, LIFO batch:31
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_smp_init_cpus] enter (9420->f3003010)
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_smp_init_cpus] ncores=4
Jan 17 22:17:01 raspberrypi kernel: PERCPU: Embedded 12 pages/cpu @bafb0000 s20416 r8192 d20544 u49152
Jan 17 22:17:01 raspberrypi kernel: pcpu-alloc: s20416 r8192 d20544 u49152 alloc=12*4096
Jan 17 22:17:01 raspberrypi kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
Jan 17 22:17:01 raspberrypi kernel: Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 239540
Jan 17 22:17:01 raspberrypi kernel: Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2709.boardrev=0xa01041 bcm2709.serial=0x579b07c1 smsc95xx.macaddr=B8:27:EB:9B:07:C1 bcm2708_fb.fbswap=1 bcm2709.uart_clock=3000000 bcm2709.disk_led_gpio=47 bcm2709.disk_led_active_low=0 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000  dwc_otg.lpm_e
Jan 17 22:17:01 raspberrypi kernel: PID hash table entries: 4096 (order: 2, 16384 bytes)
Jan 17 22:17:01 raspberrypi kernel: Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Jan 17 22:17:01 raspberrypi kernel: Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Jan 17 22:17:01 raspberrypi kernel: Memory: 939376K/966656K available (6064K kernel code, 534K rwdata, 1664K rodata, 444K init, 757K bss, 19088K reserved, 8192K cma-reserved)
Jan 17 22:17:01 raspberrypi kernel: Virtual kernel memory layout:
                                        vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                                        fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                                        vmalloc : 0xbb800000 - 0xff000000   (1080 MB)
                                        lowmem  : 0x80000000 - 0xbb000000   ( 944 MB)
                                        modules : 0x7f000000 - 0x80000000   (  16 MB)
                                          .text : 0x80008000 - 0x807945f0   (7730 kB)
                                          .init : 0x80795000 - 0x80804000   ( 444 kB)
                                          .data : 0x80804000 - 0x80889b10   ( 535 kB)
                                           .bss : 0x8088c000 - 0x809497dc   ( 758 kB)
Jan 17 22:17:01 raspberrypi kernel: SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
Jan 17 22:17:01 raspberrypi kernel: Hierarchical RCU implementation.
Jan 17 22:17:01 raspberrypi kernel:         Additional per-CPU info printed with stalls.
Jan 17 22:17:01 raspberrypi kernel: NR_IRQS:608
Jan 17 22:17:01 raspberrypi kernel: Architected cp15 timer(s) running at 19.20MHz (phys).
Jan 17 22:17:01 raspberrypi kernel: clocksource arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
Jan 17 22:17:01 raspberrypi kernel: sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
Jan 17 22:17:01 raspberrypi kernel: Switching to timer-based delay loop, resolution 52ns
Jan 17 22:17:01 raspberrypi kernel: Console: colour dummy device 80x30
Jan 17 22:17:01 raspberrypi kernel: console [tty1] enabled
Jan 17 22:17:01 raspberrypi kernel: Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
Jan 17 22:17:01 raspberrypi kernel: pid_max: default: 32768 minimum: 301
Jan 17 22:17:01 raspberrypi kernel: Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
Jan 17 22:17:01 raspberrypi kernel: Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
Jan 17 22:17:01 raspberrypi kernel: Initializing cgroup subsys blkio
Jan 17 22:17:01 raspberrypi kernel: Initializing cgroup subsys memory
Jan 17 22:17:01 raspberrypi kernel: Initializing cgroup subsys devices
Jan 17 22:17:01 raspberrypi kernel: Initializing cgroup subsys freezer
Jan 17 22:17:01 raspberrypi kernel: Initializing cgroup subsys net_cls
Jan 17 22:17:01 raspberrypi kernel: CPU: Testing write buffer coherency: ok
Jan 17 22:17:01 raspberrypi kernel: ftrace: allocating 20313 entries in 60 pages
Jan 17 22:17:01 raspberrypi kernel: CPU0: update cpu_capacity 1024
Jan 17 22:17:01 raspberrypi kernel: CPU0: thread -1, cpu 0, socket 15, mpidr 80000f00
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_smp_prepare_cpus] enter
Jan 17 22:17:01 raspberrypi kernel: Setting up static identity map for 0x8240 - 0x8274
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_boot_secondary] cpu:1 started (0) 17
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_secondary_init] enter cpu:1
Jan 17 22:17:01 raspberrypi kernel: CPU1: update cpu_capacity 1024
Jan 17 22:17:01 raspberrypi kernel: CPU1: thread -1, cpu 1, socket 15, mpidr 80000f01
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_boot_secondary] cpu:2 started (0) 18
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_secondary_init] enter cpu:2
Jan 17 22:17:01 raspberrypi kernel: CPU2: update cpu_capacity 1024
Jan 17 22:17:01 raspberrypi kernel: CPU2: thread -1, cpu 2, socket 15, mpidr 80000f02
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_boot_secondary] cpu:3 started (0) 16
Jan 17 22:17:01 raspberrypi kernel: [bcm2709_secondary_init] enter cpu:3
Jan 17 22:17:01 raspberrypi kernel: CPU3: update cpu_capacity 1024
Jan 17 22:17:01 raspberrypi kernel: CPU3: thread -1, cpu 3, socket 15, mpidr 80000f03
Jan 17 22:17:01 raspberrypi kernel: Brought up 4 CPUs
Jan 17 22:17:01 raspberrypi kernel: SMP: Total of 4 processors activated (153.60 BogoMIPS).
Jan 17 22:17:01 raspberrypi kernel: CPU: All CPU(s) started in HYP mode.
Jan 17 22:17:01 raspberrypi kernel: CPU: Virtualization extensions available.
Jan 17 22:17:01 raspberrypi kernel: devtmpfs: initialized
Jan 17 22:17:01 raspberrypi kernel: VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5
Jan 17 22:17:01 raspberrypi kernel: clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
Jan 17 22:17:01 raspberrypi kernel: pinctrl core: initialized pinctrl subsystem
Jan 17 22:17:01 raspberrypi kernel: NET: Registered protocol family 16
Jan 17 22:17:01 raspberrypi kernel: DMA: preallocated 4096 KiB pool for atomic coherent allocations
Jan 17 22:17:01 raspberrypi kernel: bcm2709.uart_clock = 3000000
Jan 17 22:17:01 raspberrypi kernel: hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
Jan 17 22:17:01 raspberrypi kernel: hw-breakpoint: maximum watchpoint size is 8 bytes.
Jan 17 22:17:01 raspberrypi kernel: Serial: AMBA PL011 UART driver
Jan 17 22:17:01 raspberrypi kernel: uart-pl011 3f201000.uart: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
Jan 17 22:17:01 raspberrypi kernel: bcm2835-mbox 3f00b880.mailbox: mailbox enabled
Jan 17 22:17:01 raspberrypi kernel: bcm2708-dmaengine 3f007000.dma: DMA legacy API manager at f3007000, dmachans=0xf35
Jan 17 22:17:01 raspberrypi kernel: bcm2708-dmaengine 3f007000.dma: Initialized 7 DMA channels (+ 1 legacy)
Jan 17 22:17:01 raspberrypi kernel: bcm2708-dmaengine 3f007000.dma: Load BCM2835 DMA engine driver
Jan 17 22:17:01 raspberrypi kernel: bcm2708-dmaengine 3f007000.dma: dma_debug:0
Jan 17 22:17:01 raspberrypi kernel: SCSI subsystem initialized
Jan 17 22:17:01 raspberrypi kernel: usbcore: registered new interface driver usbfs
Jan 17 22:17:01 raspberrypi kernel: usbcore: registered new interface driver hub
Jan 17 22:17:01 raspberrypi kernel: usbcore: registered new device driver usb
Jan 17 22:17:01 raspberrypi kernel: raspberrypi-firmware soc:firmware: Attached to firmware from 2016-03-09 18:11
Jan 17 22:17:01 raspberrypi kernel: Switched to clocksource arch_sys_counter
Jan 17 22:17:01 raspberrypi kernel: FS-Cache: Loaded
Jan 17 22:17:01 raspberrypi kernel: CacheFiles: Loaded
Jan 17 22:17:01 raspberrypi kernel: NET: Registered protocol family 2
Jan 17 22:17:01 raspberrypi kernel: TCP established hash table entries: 8192 (order: 3, 32768 bytes)
Jan 17 22:17:01 raspberrypi kernel: TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
Jan 17 22:17:01 raspberrypi kernel: TCP: Hash tables configured (established 8192 bind 8192)
Jan 17 22:17:01 raspberrypi kernel: UDP hash table entries: 512 (order: 2, 16384 bytes)
Jan 17 22:17:01 raspberrypi kernel: UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
Jan 17 22:17:01 raspberrypi kernel: NET: Registered protocol family 1
Jan 17 22:17:01 raspberrypi kernel: RPC: Registered named UNIX socket transport module.
Jan 17 22:17:01 raspberrypi kernel: RPC: Registered udp transport module.
Jan 17 22:17:01 raspberrypi kernel: RPC: Registered tcp transport module.
Jan 17 22:17:01 raspberrypi kernel: RPC: Registered tcp NFSv4.1 backchannel transport module.
Jan 17 22:17:01 raspberrypi kernel: hw perfevents: enabled with armv7_cortex_a7 PMU driver, 5 counters available
Jan 17 22:17:01 raspberrypi kernel: futex hash table entries: 1024 (order: 4, 65536 bytes)
Jan 17 22:17:01 raspberrypi kernel: VFS: Disk quotas dquot_6.6.0
Jan 17 22:17:01 raspberrypi kernel: VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Jan 17 22:17:01 raspberrypi kernel: FS-Cache: Netfs 'nfs' registered for caching
Jan 17 22:17:01 raspberrypi kernel: NFS: Registering the id_resolver key type
Jan 17 22:17:01 raspberrypi kernel: Key type id_resolver registered
Jan 17 22:17:01 raspberrypi kernel: Key type id_legacy registered
Jan 17 22:17:01 raspberrypi kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
Jan 17 22:17:01 raspberrypi kernel: io scheduler noop registered
Jan 17 22:17:01 raspberrypi kernel: io scheduler deadline registered (default)
Jan 17 22:17:01 raspberrypi kernel: io scheduler cfq registered
Jan 17 22:17:01 raspberrypi kernel: BCM2708FB: allocated DMA memory fa800000
Jan 17 22:17:01 raspberrypi kernel: BCM2708FB: allocated DMA channel 0 @ f3007000
Jan 17 22:17:01 raspberrypi kernel: Console: switching to colour frame buffer device 82x26
Jan 17 22:17:01 raspberrypi kernel: Serial: 8250/16550 driver, 0 ports, IRQ sharing disabled
Jan 17 22:17:01 raspberrypi kernel: vc-cma: Videocore CMA driver
Jan 17 22:17:01 raspberrypi kernel: vc-cma: vc_cma_base      = 0x00000000
Jan 17 22:17:01 raspberrypi kernel: vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
Jan 17 22:17:01 raspberrypi kernel: vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
Jan 17 22:17:01 raspberrypi kernel: vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000000(1008 MiB)
Jan 17 22:17:01 raspberrypi kernel: brd: module loaded
Jan 17 22:17:01 raspberrypi kernel: loop: module loaded
Jan 17 22:17:01 raspberrypi kernel: vchiq: vchiq_init_state: slot_zero = 0xba880000, is_master = 0
Jan 17 22:17:01 raspberrypi kernel: Loading iSCSI transport class v2.0-870.
Jan 17 22:17:01 raspberrypi kernel: usbcore: registered new interface driver smsc95xx
Jan 17 22:17:01 raspberrypi kernel: dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Jan 17 22:17:01 raspberrypi kernel: Core Release: 2.80a
Jan 17 22:17:01 raspberrypi kernel: Setting default values for core params
Jan 17 22:17:01 raspberrypi kernel: Finished setting default values for core params
Jan 17 22:17:01 raspberrypi kernel: Using Buffer DMA mode
Jan 17 22:17:01 raspberrypi kernel: Periodic Transfer Interrupt Enhancement - disabled
Jan 17 22:17:01 raspberrypi kernel: Multiprocessor Interrupt Enhancement - disabled
Jan 17 22:17:01 raspberrypi kernel: OTG VER PARAM: 0, OTG VER FLAG: 0
Jan 17 22:17:01 raspberrypi kernel: Dedicated Tx FIFOs mode
Jan 17 22:17:01 raspberrypi kernel: WARN::dwc_otg_hcd_init:1047: FIQ DMA bounce buffers: virt = 0xba814000 dma = 0xfa814000 len=9024
Jan 17 22:17:01 raspberrypi kernel: FIQ FSM acceleration enabled for :
                                    Non-periodic Split Transactions
                                    Periodic Split Transactions
                                    High-Speed Isochronous Endpoints
Jan 17 22:17:01 raspberrypi kernel: dwc_otg: Microframe scheduler enabled
Jan 17 22:17:01 raspberrypi kernel: WARN::hcd_init_fiq:412: FIQ on core 1 at 0x80417288
Jan 17 22:17:01 raspberrypi kernel: WARN::hcd_init_fiq:413: FIQ ASM at 0x804175f8 length 36
Jan 17 22:17:01 raspberrypi kernel: WARN::hcd_init_fiq:438: MPHI regs_base at 0xbb89a000
Jan 17 22:17:01 raspberrypi kernel: dwc_otg 3f980000.usb: DWC OTG Controller
Jan 17 22:17:01 raspberrypi kernel: dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
Jan 17 22:17:01 raspberrypi kernel: dwc_otg 3f980000.usb: irq 32, io mem 0x00000000
Jan 17 22:17:01 raspberrypi kernel: Init: Port Power? op_state=1
Jan 17 22:17:01 raspberrypi kernel: Init: Power Port (0)
Jan 17 22:17:01 raspberrypi kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Jan 17 22:17:01 raspberrypi kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jan 17 22:17:01 raspberrypi kernel: usb usb1: Product: DWC OTG Controller
Jan 17 22:17:01 raspberrypi kernel: usb usb1: Manufacturer: Linux 4.1.19-v7+ dwc_otg_hcd
Jan 17 22:17:01 raspberrypi kernel: usb usb1: SerialNumber: 3f980000.usb
Jan 17 22:17:01 raspberrypi kernel: hub 1-0:1.0: USB hub found
Jan 17 22:17:01 raspberrypi kernel: hub 1-0:1.0: 1 port detected
Jan 17 22:17:01 raspberrypi kernel: dwc_otg: FIQ enabled
Jan 17 22:17:01 raspberrypi kernel: dwc_otg: NAK holdoff enabled
Jan 17 22:17:01 raspberrypi kernel: dwc_otg: FIQ split-transaction FSM enabled
Jan 17 22:17:01 raspberrypi kernel: Module dwc_common_port init
Jan 17 22:17:01 raspberrypi kernel: usbcore: registered new interface driver usb-storage
Jan 17 22:17:01 raspberrypi kernel: mousedev: PS/2 mouse device common for all mice
Jan 17 22:17:01 raspberrypi kernel: bcm2835-cpufreq: min=600000 max=900000
Jan 17 22:17:01 raspberrypi kernel: sdhci: Secure Digital Host Controller Interface driver
Jan 17 22:17:01 raspberrypi kernel: sdhci: Copyright(c) Pierre Ossman
Jan 17 22:17:01 raspberrypi kernel: sdhost: log_buf @ ba813000 (fa813000)
Jan 17 22:17:01 raspberrypi kernel: mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
Jan 17 22:17:01 raspberrypi kernel: sdhci-pltfm: SDHCI platform and OF driver helper
Jan 17 22:17:01 raspberrypi kernel: ledtrig-cpu: registered to indicate activity on CPUs
Jan 17 22:17:01 raspberrypi kernel: hidraw: raw HID events driver (C) Jiri Kosina
Jan 17 22:17:01 raspberrypi kernel: usbcore: registered new interface driver usbhid
Jan 17 22:17:01 raspberrypi kernel: usbhid: USB HID core driver
Jan 17 22:17:01 raspberrypi kernel: Initializing XFRM netlink socket
Jan 17 22:17:01 raspberrypi kernel: NET: Registered protocol family 17
Jan 17 22:17:01 raspberrypi kernel: Key type dns_resolver registered
Jan 17 22:17:01 raspberrypi kernel: Registering SWP/SWPB emulation handler
Jan 17 22:17:01 raspberrypi kernel: registered taskstats version 1
Jan 17 22:17:01 raspberrypi kernel: vc-sm: Videocore shared memory driver
Jan 17 22:17:01 raspberrypi kernel: [vc_sm_connected_init]: start
Jan 17 22:17:01 raspberrypi kernel: [vc_sm_connected_init]: end - returning 0
Jan 17 22:17:01 raspberrypi kernel: 3f201000.uart: ttyAMA0 at MMIO 0x3f201000 (irq = 83, base_baud = 0) is a PL011 rev2
Jan 17 22:17:01 raspberrypi kernel: mmc0: host does not support reading read-only switch, assuming write-enable
Jan 17 22:17:01 raspberrypi kernel: mmc0: new high speed SDHC card at address 59b4
Jan 17 22:17:01 raspberrypi kernel: mmcblk0: mmc0:59b4 USD00 29.5 GiB
Jan 17 22:17:01 raspberrypi kernel:  mmcblk0: p1 p2
Jan 17 22:17:01 raspberrypi kernel: Indeed it is in host mode hprt0 = 00021501
Jan 17 22:17:01 raspberrypi kernel: usb 1-1: new high-speed USB device number 2 using dwc_otg
Jan 17 22:17:01 raspberrypi kernel: Indeed it is in host mode hprt0 = 00001101
Jan 17 22:17:01 raspberrypi kernel: usb 1-1: New USB device found, idVendor=0424, idProduct=9514
Jan 17 22:17:01 raspberrypi kernel: usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Jan 17 22:17:01 raspberrypi kernel: hub 1-1:1.0: USB hub found
Jan 17 22:17:01 raspberrypi kernel: hub 1-1:1.0: 5 ports detected
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Jan 17 22:17:01 raspberrypi kernel: smsc95xx v1.0.4
Jan 17 22:17:01 raspberrypi kernel: smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:9b:07:c1
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.5: new high-speed USB device number 4 using dwc_otg
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.5: New USB device found, idVendor=2357, idProduct=0101
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.5: Product: 802.11n NIC
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.5: Manufacturer: Realtek
Jan 17 22:17:01 raspberrypi kernel: usb 1-1.5: SerialNumber: 123456
Jan 17 22:17:01 raspberrypi kernel: console [ttyAMA0] enabled
Jan 17 22:17:01 raspberrypi kernel: EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
Jan 17 22:17:01 raspberrypi kernel: EXT4-fs (mmcblk0p2): write access will be enabled during recovery
Jan 17 22:17:01 raspberrypi kernel: EXT4-fs (mmcblk0p2): recovery complete
Jan 17 22:17:01 raspberrypi kernel: EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Jan 17 22:17:01 raspberrypi kernel: VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
Jan 17 22:17:01 raspberrypi kernel: devtmpfs: mounted
Jan 17 22:17:01 raspberrypi kernel: Freeing unused kernel memory: 444K (80795000 - 80804000)
Jan 17 22:17:01 raspberrypi kernel: random: systemd urandom read with 74 bits of entropy available
Jan 17 22:17:01 raspberrypi systemd[1]: systemd 215 running in system mode. (+PAM +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -SECCOMP -APPARMOR)
Jan 17 22:17:01 raspberrypi systemd[1]: Detected architecture 'arm'.
Jan 17 22:17:01 raspberrypi kernel: NET: Registered protocol family 10
Jan 17 22:17:01 raspberrypi systemd[1]: Inserted module 'ipv6'
Jan 17 22:17:01 raspberrypi systemd[1]: Set hostname to <raspberrypi>.
Jan 17 22:17:01 raspberrypi kernel: uart-pl011 3f201000.uart: no DMA platform data
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
Jan 17 22:17:01 raspberrypi systemd[1]: Started Forward Password Requests to Wall Directory Watch.
Jan 17 22:17:01 raspberrypi systemd[1]: Expecting device dev-ttyAMA0.device...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Remote File Systems (Pre).
Jan 17 22:17:01 raspberrypi systemd[1]: Reached target Remote File Systems (Pre).
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Arbitrary Executable File Formats File System Automount Point.
Jan 17 22:17:01 raspberrypi systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Encrypted Volumes.
Jan 17 22:17:01 raspberrypi systemd[1]: Reached target Encrypted Volumes.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Swap.
Jan 17 22:17:01 raspberrypi systemd[1]: Reached target Swap.
Jan 17 22:17:01 raspberrypi systemd[1]: Expecting device dev-mmcblk0p1.device...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Root Slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Created slice Root Slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting User and Session Slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Created slice User and Session Slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Delayed Shutdown Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Listening on Delayed Shutdown Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting /dev/initctl Compatibility Named Pipe.
Jan 17 22:17:01 raspberrypi systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Journal Socket (/dev/log).
Jan 17 22:17:01 raspberrypi systemd[1]: Listening on Journal Socket (/dev/log).
Jan 17 22:17:01 raspberrypi systemd[1]: Starting udev Control Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Listening on udev Control Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting udev Kernel Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Listening on udev Kernel Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Journal Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Listening on Journal Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting System Slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Created slice System Slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting File System Check on Root Device...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting system-systemd\x2dfsck.slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Created slice system-systemd\x2dfsck.slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting system-autologin.slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Created slice system-autologin.slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting system-serial\x2dgetty.slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Created slice system-serial\x2dgetty.slice.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Increase datagram queue length...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Restore / save the current clock...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting udev Coldplug all Devices...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Load Kernel Modules...
Jan 17 22:17:01 raspberrypi systemd[1]: Mounting Debug File System...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Create list of required static device nodes for the current kernel...
Jan 17 22:17:01 raspberrypi systemd[1]: Mounted Huge Pages File System.
Jan 17 22:17:01 raspberrypi systemd[1]: Started Set Up Additional Binary Formats.
Jan 17 22:17:01 raspberrypi systemd[1]: Mounting POSIX Message Queue File System...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Slices.
Jan 17 22:17:01 raspberrypi systemd[1]: Reached target Slices.
Jan 17 22:17:01 raspberrypi kernel: fuse init (API version 7.23)
Jan 17 22:17:01 raspberrypi systemd[1]: Mounted POSIX Message Queue File System.
Jan 17 22:17:01 raspberrypi systemd[1]: Mounted Debug File System.
Jan 17 22:17:01 raspberrypi systemd[1]: Started Increase datagram queue length.
Jan 17 22:17:01 raspberrypi kernel: i2c /dev entries driver
Jan 17 22:17:01 raspberrypi systemd[1]: Started Restore / save the current clock.
Jan 17 22:17:01 raspberrypi systemd[1]: Started Load Kernel Modules.
Jan 17 22:17:01 raspberrypi systemd[1]: Started Create list of required static device nodes for the current kernel.
Jan 17 22:17:01 raspberrypi systemd[1]: Time has been changed
Jan 17 22:17:01 raspberrypi systemd[1]: Started File System Check on Root Device.
Jan 17 22:17:01 raspberrypi systemd[1]: Started udev Coldplug all Devices.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Create Static Device Nodes in /dev...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Apply Kernel Variables...
Jan 17 22:17:01 raspberrypi systemd[1]: Mounting Configuration File System...
Jan 17 22:17:01 raspberrypi systemd[1]: Mounting FUSE Control File System...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Syslog Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Listening on Syslog Socket.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Journal Service...
Jan 17 22:17:01 raspberrypi systemd[1]: Started Journal Service.
Jan 17 22:17:01 raspberrypi systemd-udevd[108]: starting version 215
Jan 17 22:17:01 raspberrypi systemd-journal[106]: Journal started
Jan 17 22:17:01 raspberrypi systemd-modules-load[78]: Inserted module 'fuse'
Jan 17 22:17:01 raspberrypi systemd-modules-load[78]: Inserted module 'i2c_dev'
Jan 17 22:17:01 raspberrypi systemd[1]: Mounted FUSE Control File System.
Jan 17 22:17:01 raspberrypi systemd[1]: Mounted Configuration File System.
Jan 17 22:17:01 raspberrypi systemd[1]: Started Apply Kernel Variables.
Jan 17 22:17:01 raspberrypi systemd[1]: Started Create Static Device Nodes in /dev.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting udev Kernel Device Manager...
Jan 17 22:17:01 raspberrypi systemd[1]: Started udev Kernel Device Manager.
Jan 17 22:17:01 raspberrypi systemd[1]: Starting Copy rules generated while the root was ro...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting LSB: Tune IDE hard disks...
Jan 17 22:17:01 raspberrypi systemd[1]: Starting LSB: Set preliminary keymap...
Jan 17 22:17:01 raspberrypi systemd-fsck[72]: e2fsck 1.42.12 (29-Aug-2014)
Jan 17 22:17:01 raspberrypi systemd-fsck[72]: /dev/mmcblk0p2: clean, 146020/258048 files, 948949/1024000 blocks
Jan 17 22:17:01 raspberrypi fake-hwclock[75]: Tue 17 Jan 22:17:01 UTC 2017
Jan 17 22:17:01 raspberrypi hdparm[110]: Setting parameters of disc: (none).
Jan 17 22:17:01 raspberrypi systemd[1]: Started LSB: Tune IDE hard disks.
Jan 17 22:17:02 raspberrypi kernel: bcm2708_i2c 3f804000.i2c: BSC1 Controller at 0x3f804000 (irq 79) (baudrate 100000)
Jan 17 22:17:01 raspberrypi systemd[1]: Found device /dev/ttyAMA0.
Jan 17 22:17:02 raspberrypi keyboard-setup[112]: Setting preliminary keymap...done.
Jan 17 22:17:02 raspberrypi systemd[1]: Started LSB: Set preliminary keymap.
Jan 17 22:17:02 raspberrypi systemd[1]: Started Show Plymouth Boot Screen.
Jan 17 22:17:02 raspberrypi systemd[1]: Started Forward Password Requests to Plymouth Directory Watch.
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Dispatch Password Requests to Console Directory Watch.
Jan 17 22:17:02 raspberrypi systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Paths.
Jan 17 22:17:02 raspberrypi systemd[1]: Reached target Paths.
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Remount Root and Kernel File Systems...
Jan 17 22:17:02 raspberrypi kernel: snd-hifiberry-digi sound: ASoC: CPU DAI (null) not registered
Jan 17 22:17:02 raspberrypi kernel: snd-hifiberry-digi sound: snd_soc_register_card() failed: -517
Jan 17 22:17:02 raspberrypi kernel: EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Jan 17 22:17:02 raspberrypi systemd-udevd[180]: failed to execute '/lib/udev/mtp-probe' 'mtp-probe /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1 1 3': No such file or directory
Jan 17 22:17:02 raspberrypi systemd[1]: Started Remount Root and Kernel File Systems.
Jan 17 22:17:02 raspberrypi systemd[1]: Started Various fixups to make systemd work better on Debian.
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Load/Save Random Seed...
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Local File Systems (Pre).
Jan 17 22:17:02 raspberrypi systemd[1]: Reached target Local File Systems (Pre).
Jan 17 22:17:02 raspberrypi systemd[1]: Found device /dev/mmcblk0p1.
Jan 17 22:17:02 raspberrypi systemd[1]: Started Load/Save Random Seed.
Jan 17 22:17:02 raspberrypi systemd-udevd[181]: failed to execute '/lib/udev/mtp-probe' 'mtp-probe /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5 1 4': No such file or directory
Jan 17 22:17:02 raspberrypi systemd[1]: Starting File System Check on /dev/mmcblk0p1...
Jan 17 22:17:02 raspberrypi kernel: cfg80211: Calling CRDA to update world regulatory domain
Jan 17 22:17:02 raspberrypi systemd-fsck[193]: fsck.fat 3.0.27 (2014-11-12)
Jan 17 22:17:02 raspberrypi systemd-fsck[193]: 0x25: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
Jan 17 22:17:02 raspberrypi systemd-fsck[193]: Automatically removing dirty bit.
Jan 17 22:17:02 raspberrypi systemd-fsck[193]: Performing changes.
Jan 17 22:17:02 raspberrypi systemd-fsck[193]: /dev/mmcblk0p1: 84 files, 2549/7673 clusters
Jan 17 22:17:02 raspberrypi systemd[1]: Started File System Check on /dev/mmcblk0p1.
Jan 17 22:17:02 raspberrypi systemd[1]: Mounting /boot...
Jan 17 22:17:02 raspberrypi kernel: bcm2835-rng 3f104000.rng: hwrng registered
Jan 17 22:17:02 raspberrypi kernel: gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
Jan 17 22:17:02 raspberrypi kernel: snd-hifiberry-digi sound: ASoC: CODEC DAI wm8804-spdif not registered
Jan 17 22:17:02 raspberrypi kernel: snd-hifiberry-digi sound: snd_soc_register_card() failed: -517
Jan 17 22:17:02 raspberrypi kernel: RTL871X: module init start
Jan 17 22:17:02 raspberrypi kernel: RTL871X: rtl8821au v4.3.14_13455.20150212_BTCOEX20150128-51
Jan 17 22:17:02 raspberrypi kernel: RTL871X: build time: Mar 13 2016 17:36:23
Jan 17 22:17:02 raspberrypi kernel: RTL871X: rtl8821au BT-Coex version = BTCOEX20150128-51
Jan 17 22:17:02 raspberrypi systemd[1]: Mounted /boot.
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Local File Systems.
Jan 17 22:17:02 raspberrypi systemd[1]: Reached target Local File Systems.
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Tell Plymouth To Write Out Runtime Data...
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Create Volatile Files and Directories...
Jan 17 22:17:02 raspberrypi systemd[1]: Starting LSB: Raise network interfaces....
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Remote File Systems.
Jan 17 22:17:02 raspberrypi systemd[1]: Reached target Remote File Systems.
Jan 17 22:17:02 raspberrypi systemd[1]: Starting Trigger Flushing of Journal to Persistent Storage...
Jan 17 22:17:02 raspberrypi systemd[1]: Starting LSB: Prepare console...
Jan 17 22:17:02 raspberrypi systemd[1]: Starting LSB: Switch to ondemand cpu governor (unless shift key is pressed)...
Jan 17 22:17:02 raspberrypi systemd[1]: Started Tell Plymouth To Write Out Runtime Data.
Jan 17 22:17:02 raspberrypi systemd[1]: Started Create Volatile Files and Directories.
Jan 17 22:17:03 raspberrypi kernel: wm8804 1-003b: revision E
Jan 17 22:17:03 raspberrypi kernel: snd-hifiberry-digi sound: wm8804-spdif <-> 3f203000.i2s mapping ok
Jan 17 22:17:03 raspberrypi raspi-config[210]: Checking if shift key is held down:Error opening '/dev/input/event*': No such file or directory
Jan 17 22:17:03 raspberrypi systemd-journal[106]: Runtime journal is using 5.7M (max allowed 46.2M, trying to leave 69.4M free of 456.8M available → current limit 46.2M).
Jan 17 22:17:03 raspberrypi raspi-config[210]: No. Switching to ondemand scaling governor.
Jan 17 22:17:03 raspberrypi kbd[208]: Setting console screen modes.
Jan 17 22:17:03 raspberrypi systemd[1]: Started Trigger Flushing of Journal to Persistent Storage.
Jan 17 22:17:03 raspberrypi systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Jan 17 22:17:03 raspberrypi systemd[1]: Starting Sound Card.
Jan 17 22:17:03 raspberrypi systemd[1]: Reached target Sound Card.
Jan 17 22:17:03 raspberrypi systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Jan 17 22:17:03 raspberrypi kernel: random: nonblocking pool is initialized
Jan 17 22:17:03 raspberrypi systemd[1]: Started Update UTMP about System Boot/Shutdown.
Jan 17 22:17:03 raspberrypi kernel: RTL871X: rtw_ndev_init(wlan0)
Jan 17 22:17:03 raspberrypi kernel: usbcore: registered new interface driver rtl8821au
Jan 17 22:17:03 raspberrypi kernel: RTL871X: module init ret=0
Jan 17 22:17:03 raspberrypi kbd[208]: setterm: $TERM is not defined.
Jan 17 22:17:03 raspberrypi systemd[1]: Started LSB: Prepare console.
Jan 17 22:17:03 raspberrypi kernel: cfg80211: World regulatory domain updated:
Jan 17 22:17:03 raspberrypi kernel: cfg80211:  DFS Master region: unset
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (2457000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
Jan 17 22:17:03 raspberrypi kernel: cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
Jan 17 22:17:03 raspberrypi systemd[1]: Starting system-systemd\x2drfkill.slice.
Jan 17 22:17:03 raspberrypi systemd[1]: Created slice system-systemd\x2drfkill.slice.
Jan 17 22:17:03 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status of rfkill0...
Jan 17 22:17:03 raspberrypi systemd[1]: Starting LSB: Set console font and keymap...
Jan 17 22:17:03 raspberrypi systemd[1]: Starting system-ifup.slice.
Jan 17 22:17:03 raspberrypi systemd[1]: Created slice system-ifup.slice.
Jan 17 22:17:03 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status of rfkill0.
Jan 17 22:17:03 raspberrypi wpa_supplicant[339]: Successfully initialized wpa_supplicant
Jan 17 22:17:03 raspberrypi console-setup[273]: Setting up console font and keymap...done.
Jan 17 22:17:03 raspberrypi systemd[1]: Started LSB: Set console font and keymap.
Jan 17 22:17:04 raspberrypi kernel: IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 17 22:17:04 raspberrypi dhclient[358]: Internet Systems Consortium DHCP Client 4.3.1
Jan 17 22:17:04 raspberrypi dhclient[358]: Copyright 2004-2014 Internet Systems Consortium.
Jan 17 22:17:04 raspberrypi dhclient[358]: All rights reserved.
Jan 17 22:17:04 raspberrypi dhclient[358]: For info, please visit https://www.isc.org/software/dhcp/
Jan 17 22:17:04 raspberrypi dhclient[358]:
Jan 17 22:17:04 raspberrypi networking[205]: Configuring network interfaces...Internet Systems Consortium DHCP Client 4.3.1
Jan 17 22:17:04 raspberrypi networking[205]: Copyright 2004-2014 Internet Systems Consortium.
Jan 17 22:17:04 raspberrypi networking[205]: All rights reserved.
Jan 17 22:17:04 raspberrypi networking[205]: For info, please visit https://www.isc.org/software/dhcp/
Jan 17 22:17:04 raspberrypi dhclient[358]: Listening on LPF/wlan0/98:de:d0:07:cd:82
Jan 17 22:17:04 raspberrypi dhclient[358]: Sending on   LPF/wlan0/98:de:d0:07:cd:82
Jan 17 22:17:04 raspberrypi dhclient[358]: Sending on   Socket/fallback
Jan 17 22:17:04 raspberrypi dhclient[358]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jan 17 22:17:04 raspberrypi networking[205]: Listening on LPF/wlan0/98:de:d0:07:cd:82
Jan 17 22:17:04 raspberrypi networking[205]: Sending on   LPF/wlan0/98:de:d0:07:cd:82
Jan 17 22:17:04 raspberrypi networking[205]: Sending on   Socket/fallback
Jan 17 22:17:04 raspberrypi networking[205]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jan 17 22:17:08 raspberrypi wpa_supplicant[343]: wlan0: Trying to associate with a4:2b:b0:f2:85:c5 (SSID='MK's Wifi' freq=2462 MHz)
Jan 17 22:17:08 raspberrypi kernel: RTL871X: rtw_set_802_11_connect(wlan0)  fw_state=0x00000008
Jan 17 22:17:09 raspberrypi kernel: RTL871X: start auth
Jan 17 22:17:09 raspberrypi kernel: RTL871X: auth success, start assoc
Jan 17 22:17:09 raspberrypi kernel: RTL871X: rtw_cfg80211_indicate_connect(wlan0) BSS not found !!
Jan 17 22:17:09 raspberrypi kernel: RTL871X: assoc success
Jan 17 22:17:09 raspberrypi kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 17 22:17:09 raspberrypi wpa_supplicant[343]: wlan0: Associated with a4:2b:b0:f2:85:c5
Jan 17 22:17:09 raspberrypi kernel: RTL871X: send eapol packet
Jan 17 22:17:09 raspberrypi wpa_supplicant[343]: wlan0: WPA: Key negotiation completed with a4:2b:b0:f2:85:c5 [PTK=CCMP GTK=TKIP]
Jan 17 22:17:09 raspberrypi wpa_supplicant[343]: wlan0: CTRL-EVENT-CONNECTED - Connection to a4:2b:b0:f2:85:c5 completed [id=0 id_str=]
Jan 17 22:17:09 raspberrypi kernel: RTL871X: send eapol packet
Jan 17 22:17:09 raspberrypi kernel: RTL871X: set pairwise key camid:4, addr:a4:2b:b0:f2:85:c5, kid:0, type:AES
Jan 17 22:17:09 raspberrypi kernel: RTL871X: set group key camid:5, addr:a4:2b:b0:f2:85:c5, kid:1, type:TKIP
Jan 17 22:17:09 raspberrypi dhclient[358]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jan 17 22:17:09 raspberrypi networking[205]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jan 17 22:17:09 raspberrypi dhclient[358]: DHCPACK from 192.168.0.1
Jan 17 22:17:09 raspberrypi networking[205]: DHCPACK from 192.168.0.1
Jan 17 22:17:09 raspberrypi dhclient[358]: bound to 192.168.0.162 -- renewal in 2868 seconds.
Jan 17 22:17:09 raspberrypi networking[205]: bound to 192.168.0.162 -- renewal in 2868 seconds.
Jan 17 22:17:10 raspberrypi networking[205]: ifup: interface wlan0 already configured
Jan 17 22:17:10 raspberrypi networking[205]: done.
Jan 17 22:17:10 raspberrypi systemd[1]: Started LSB: Raise network interfaces..
Jan 17 22:17:10 raspberrypi systemd[1]: Starting ifup for wlan0...
Jan 17 22:17:10 raspberrypi systemd[1]: Started ifup for wlan0.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting System Initialization.
Jan 17 22:17:10 raspberrypi systemd[1]: Reached target System Initialization.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack Activation Socket.
Jan 17 22:17:10 raspberrypi systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting D-Bus System Message Bus Socket.
Jan 17 22:17:10 raspberrypi systemd[1]: Listening on D-Bus System Message Bus Socket.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Sockets.
Jan 17 22:17:10 raspberrypi systemd[1]: Reached target Sockets.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Daily Cleanup of Temporary Directories.
Jan 17 22:17:10 raspberrypi systemd[1]: Started Daily Cleanup of Temporary Directories.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Timers.
Jan 17 22:17:10 raspberrypi systemd[1]: Reached target Timers.
Jan 17 22:17:10 raspberrypi systemd[1]: Started Manage Sound Card State (restore and store).
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Restore Sound Card State...
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Basic System.
Jan 17 22:17:10 raspberrypi systemd[1]: Reached target Basic System.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Regular background program processing daemon...
Jan 17 22:17:10 raspberrypi systemd[1]: Started Regular background program processing daemon.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting dhcpcd on all interfaces...
Jan 17 22:17:10 raspberrypi systemd[1]: Started Configure Bluetooth Modems connected by UART.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Login Service...
Jan 17 22:17:10 raspberrypi cron[469]: (CRON) INFO (pidfile fd = 3)
Jan 17 22:17:10 raspberrypi systemd[1]: Started getty on tty2-tty6 if dbus and logind are not available.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting LSB: triggerhappy hotkey daemon...
Jan 17 22:17:10 raspberrypi ifup[466]: /sbin/ifup: interface wlan0 already configured
Jan 17 22:17:10 raspberrypi systemd[1]: Starting LSB: Autogenerate and use a swap file...
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Jan 17 22:17:10 raspberrypi systemd[1]: Starting D-Bus System Message Bus...
Jan 17 22:17:10 raspberrypi dhcpcd[470]: version 6.7.1 starting
Jan 17 22:17:10 raspberrypi systemd[1]: Started D-Bus System Message Bus.
Jan 17 22:17:10 raspberrypi dphys-swapfile[474]: Starting dphys-swapfile swapfile setup ...
Jan 17 22:17:10 raspberrypi dhcpcd[470]: dev: loaded udev
Jan 17 22:17:10 raspberrypi cron[469]: (CRON) INFO (Running @reboot jobs)
Jan 17 22:17:10 raspberrypi dhcpcd[470]: eth0: adding address fe80::916a:c8d:e457:537c
Jan 17 22:17:10 raspberrypi dhcpcd[470]: forked to background, child pid 484
Jan 17 22:17:10 raspberrypi triggerhappy[472]: Error opening '/dev/input/event*': No such file or directory
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Found user 'avahi' (UID 105) and group 'avahi' (GID 110).
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Successfully dropped root privileges.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: avahi-daemon 0.6.31 starting up.
Jan 17 22:17:10 raspberrypi dphys-swapfile[474]: want /var/swap=100MByte, checking existing: keeping it
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Successfully called chroot().
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Successfully dropped remaining capabilities.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Loading service file /services/udisks.service.
Jan 17 22:17:10 raspberrypi dbus[477]: [system] Successfully activated service 'org.freedesktop.systemd1'
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::9ade:d0ff:fe07:cd82.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: New relevant interface wlan0.IPv6 for mDNS.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.162.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: New relevant interface wlan0.IPv4 for mDNS.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Network interface enumeration completed.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Registering new address record for fe80::9ade:d0ff:fe07:cd82 on wlan0.*.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Registering new address record for 192.168.0.162 on wlan0.IPv4.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Registering HINFO record with values 'ARMV7L'/'LINUX'.
Jan 17 22:17:10 raspberrypi kernel: Adding 102396k swap on /var/swap.  Priority:-1 extents:2 across:176124k SSFS
Jan 17 22:17:10 raspberrypi systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting System Logging Service...
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Permit User Sessions...
Jan 17 22:17:10 raspberrypi dphys-swapfile[474]: done.
Jan 17 22:17:10 raspberrypi systemd[1]: Started Restore Sound Card State.
Jan 17 22:17:10 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Jan 17 22:17:10 raspberrypi systemd[1]: Started LSB: triggerhappy hotkey daemon.
Jan 17 22:17:10 raspberrypi systemd[1]: Started LSB: Autogenerate and use a swap file.
Jan 17 22:17:10 raspberrypi systemd[1]: Started Permit User Sessions.
Jan 17 22:17:10 raspberrypi systemd[1]: Started System Logging Service.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Light Display Manager...
Jan 17 22:17:10 raspberrypi systemd-logind[471]: New seat seat0.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Network.
Jan 17 22:17:10 raspberrypi systemd[1]: Reached target Network.
Jan 17 22:17:10 raspberrypi dhcpcd[484]: eth0: waiting for carrier
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::916a:c8d:e457:537c.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: New relevant interface eth0.IPv6 for mDNS.
Jan 17 22:17:10 raspberrypi avahi-daemon[475]: Registering new address record for fe80::916a:c8d:e457:537c on eth0.*.
Jan 17 22:17:10 raspberrypi dhcpcd[484]: DUID 00:01:00:01:1e:62:73:08:b8:27:eb:17:99:83
Jan 17 22:17:10 raspberrypi dhcpcd[484]: wlan0: IAID d0:07:cd:82
Jan 17 22:17:10 raspberrypi kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Jan 17 22:17:10 raspberrypi kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Jan 17 22:17:10 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server...
Jan 17 22:17:10 raspberrypi systemd[1]: Started OpenBSD Secure Shell server.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting /etc/rc.local Compatibility...
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Network is Online.
Jan 17 22:17:10 raspberrypi systemd[1]: Reached target Network is Online.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting ShairportSync AirTunes receiver...
Jan 17 22:17:10 raspberrypi systemd[1]: Started ShairportSync AirTunes receiver.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting LSB: Start NTP daemon...
Jan 17 22:17:10 raspberrypi systemd[1]: Started /etc/rc.local Compatibility.
Jan 17 22:17:10 raspberrypi systemd[1]: Started Login Service.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Terminate Plymouth Boot Screen...
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Wait for Plymouth Boot Screen to Quit...
Jan 17 22:17:10 raspberrypi systemd[1]: Started Wait for Plymouth Boot Screen to Quit.
Jan 17 22:17:10 raspberrypi systemd[1]: Started Terminate Plymouth Boot Screen.
Jan 17 22:17:10 raspberrypi shairport-sync[560]: Successful Startup
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Getty on tty1...
Jan 17 22:17:10 raspberrypi systemd[1]: Started Getty on tty1.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Serial Getty on ttyAMA0...
Jan 17 22:17:10 raspberrypi systemd[1]: Started Serial Getty on ttyAMA0.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Login Prompts.
Jan 17 22:17:10 raspberrypi systemd[1]: Reached target Login Prompts.
Jan 17 22:17:10 raspberrypi ntpd[575]: ntpd 4.2.6p5@1.2349-o Mon Nov  2 04:29:47 UTC 2015 (1)
Jan 17 22:17:10 raspberrypi ntp[562]: Starting NTP server: ntpd.
Jan 17 22:17:10 raspberrypi ntpd[581]: proto: precision = 0.833 usec
Jan 17 22:17:10 raspberrypi ntpd[581]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Jan 17 22:17:10 raspberrypi systemd[1]: Started LSB: Start NTP daemon.
Jan 17 22:17:10 raspberrypi systemd[1]: Starting Multi-User System.
Jan 17 22:17:10 raspberrypi systemd[1]: Reached target Multi-User System.
Jan 17 22:17:10 raspberrypi ntpd[581]: Listen and drop on 1 v6wildcard :: UDP 123
Jan 17 22:17:10 raspberrypi ntpd[581]: Listen normally on 2 lo 127.0.0.1 UDP 123
Jan 17 22:17:10 raspberrypi ntpd[581]: Listen normally on 3 wlan0 192.168.0.162 UDP 123
Jan 17 22:17:10 raspberrypi ntpd[581]: Listen normally on 4 lo ::1 UDP 123
Jan 17 22:17:10 raspberrypi ntpd[581]: peers refreshed
Jan 17 22:17:10 raspberrypi ntpd[581]: Listening on routing socket on fd #21 for interface updates
Jan 17 22:17:10 raspberrypi sshd[558]: Server listening on 0.0.0.0 port 22.
Jan 17 22:17:10 raspberrypi sshd[558]: Server listening on :: port 22.
Jan 17 22:17:10 raspberrypi dhcpcd[484]: wlan0: rebinding lease of 192.168.0.162
Jan 17 22:17:10 raspberrypi dhcpcd[484]: wlan0: changing route to 192.168.0.0/24
Jan 17 22:17:10 raspberrypi dhcpcd[484]: wlan0: changing default route via 192.168.0.1
Jan 17 22:17:10 raspberrypi dhcpcd[484]: wlan0: soliciting an IPv6 router
Jan 17 22:17:11 raspberrypi lightdm[565]: ** (lightdm:565): WARNING **: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Accounts was not provided by any .service files
Jan 17 22:17:11 raspberrypi systemd[1]: Started Light Display Manager.
Jan 17 22:17:11 raspberrypi systemd[1]: Starting Graphical Interface.
Jan 17 22:17:11 raspberrypi systemd[1]: Reached target Graphical Interface.
Jan 17 22:17:11 raspberrypi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Jan 17 22:17:11 raspberrypi systemd[1]: Started Update UTMP about System Runlevel Changes.
Jan 17 22:17:11 raspberrypi systemd[1]: Startup finished in 3.633s (kernel) + 11.453s (userspace) = 15.087s.
Jan 17 22:17:11 raspberrypi avahi-daemon[475]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 512317262.
Jan 17 22:17:11 raspberrypi login[578]: pam_unix(login:session): session opened for user pi by LOGIN(uid=0)
Jan 17 22:17:11 raspberrypi systemd[1]: Starting user-1000.slice.
Jan 17 22:17:11 raspberrypi systemd[1]: Created slice user-1000.slice.
Jan 17 22:17:11 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Jan 17 22:17:11 raspberrypi systemd[1]: Starting Session c1 of user pi.
Jan 17 22:17:11 raspberrypi systemd-logind[471]: New session c1 of user pi.
Jan 17 22:17:11 raspberrypi systemd[1]: Started Session c1 of user pi.
Jan 17 22:17:11 raspberrypi systemd[643]: pam_unix(systemd-user:session): session opened for user pi by (uid=0)
Jan 17 22:17:11 raspberrypi systemd[643]: Starting Paths.
Jan 17 22:17:11 raspberrypi systemd[643]: Reached target Paths.
Jan 17 22:17:11 raspberrypi systemd[643]: Starting Timers.
Jan 17 22:17:11 raspberrypi systemd[643]: Reached target Timers.
Jan 17 22:17:11 raspberrypi systemd[643]: Starting Sockets.
Jan 17 22:17:11 raspberrypi systemd[643]: Reached target Sockets.
Jan 17 22:17:11 raspberrypi systemd[643]: Starting Basic System.
Jan 17 22:17:11 raspberrypi systemd[643]: Reached target Basic System.
Jan 17 22:17:11 raspberrypi systemd[643]: Starting Default.
Jan 17 22:17:11 raspberrypi systemd[643]: Reached target Default.
Jan 17 22:17:11 raspberrypi systemd[643]: Startup finished in 38ms.
Jan 17 22:17:11 raspberrypi systemd[1]: Started User Manager for UID 1000.
Jan 17 22:17:12 raspberrypi avahi-daemon[475]: Service "raspberrypi" (/services/udisks.service) successfully established.
Jan 17 22:17:12 raspberrypi ntpd[581]: Listen normally on 5 wlan0 fe80::9ade:d0ff:fe07:cd82 UDP 123
Jan 17 22:17:12 raspberrypi ntpd[581]: peers refreshed
Jan 17 22:17:13 raspberrypi lightdm[565]: ** (process:676): WARNING **: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Accounts was not provided by any .service files
Jan 17 22:17:13 raspberrypi lightdm[676]: pam_unix(lightdm-autologin:session): session opened for user pi by (uid=0)
Jan 17 22:17:13 raspberrypi systemd[1]: Starting Session c2 of user pi.
Jan 17 22:17:13 raspberrypi systemd[1]: Started Session c2 of user pi.
Jan 17 22:17:13 raspberrypi systemd-logind[471]: New session c2 of user pi.
Jan 17 22:17:15 raspberrypi dbus[477]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkitd.service'
Jan 17 22:17:15 raspberrypi systemd[1]: Starting Authenticate and Authorize Users to Run Privileged Tasks...
Jan 17 22:17:16 raspberrypi polkitd[754]: started daemon version 0.105 using authority implementation `local' version `0.105'
Jan 17 22:17:16 raspberrypi dbus[477]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
Jan 17 22:17:16 raspberrypi systemd[1]: Started Authenticate and Authorize Users to Run Privileged Tasks.
Jan 17 22:17:16 raspberrypi polkitd(authority=local)[754]: Registered Authentication Agent for unix-session:c2 (system bus name :1.8 [lxpolkit], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_GB.UTF-8)
Jan 17 22:17:16 raspberrypi dbus[477]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service'
Jan 17 22:17:16 raspberrypi systemd[1]: Starting Disk Manager...
Jan 17 22:17:16 raspberrypi udisksd[763]: udisks daemon version 2.1.3 starting
Jan 17 22:17:16 raspberrypi dbus[477]: [system] Successfully activated service 'org.freedesktop.UDisks2'
Jan 17 22:17:16 raspberrypi systemd[1]: Started Disk Manager.
Jan 17 22:17:16 raspberrypi udisksd[763]: Acquired the name org.freedesktop.UDisks2 on the system message bus
Jan 17 22:17:17 raspberrypi org.gtk.Private.AfcVolumeMonitor[717]: Volume monitor alive
Jan 17 22:54:21 raspberrypi systemd[643]: Time has been changed
Jan 17 22:54:21 raspberrypi systemd[1]: Time has been changed
Jan 17 22:54:26 raspberrypi dhcpcd[484]: wlan0: no IPv6 Routers available
Jan 17 23:09:00 raspberrypi systemd[1]: Starting Cleanup of Temporary Directories...
Jan 17 23:09:00 raspberrypi systemd[1]: Started Cleanup of Temporary Directories.
Jan 17 23:17:01 raspberrypi CRON[827]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 17 23:17:01 raspberrypi CRON[834]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 17 23:17:01 raspberrypi CRON[827]: pam_unix(cron:session): session closed for user root
Jan 17 23:42:01 raspberrypi dhclient[411]: DHCPREQUEST on wlan0 to 192.168.0.1 port 67
Jan 17 23:42:01 raspberrypi dhclient[411]: DHCPACK from 192.168.0.1
Jan 17 23:42:01 raspberrypi dhclient[411]: bound to 192.168.0.162 -- renewal in 3342 seconds.
Jan 18 00:17:01 raspberrypi CRON[984]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 18 00:17:01 raspberrypi CRON[991]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 18 00:17:02 raspberrypi CRON[984]: pam_unix(cron:session): session closed for user root
Jan 18 00:37:44 raspberrypi dhclient[411]: DHCPREQUEST on wlan0 to 192.168.0.1 port 67
Jan 18 00:37:44 raspberrypi dhclient[411]: DHCPACK from 192.168.0.1
Jan 18 00:37:44 raspberrypi dhclient[411]: bound to 192.168.0.162 -- renewal in 2390 seconds.
Jan 18 01:17:01 raspberrypi CRON[1142]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 18 01:17:01 raspberrypi CRON[1149]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 18 01:17:01 raspberrypi CRON[1142]: pam_unix(cron:session): session closed for user root
Jan 18 01:17:34 raspberrypi dhclient[411]: DHCPREQUEST on wlan0 to 192.168.0.1 port 67
Jan 18 01:17:34 raspberrypi dhclient[411]: DHCPACK from 192.168.0.1
Jan 18 01:17:34 raspberrypi dhclient[411]: bound to 192.168.0.162 -- renewal in 2751 seconds.
Jan 18 01:19:34 raspberrypi sshd[1211]: Accepted password for pi from 192.168.0.101 port 51938 ssh2
Jan 18 01:19:34 raspberrypi sshd[1211]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Jan 18 01:19:34 raspberrypi systemd[1]: Starting Session c3 of user pi.
Jan 18 01:19:34 raspberrypi systemd[1]: Started Session c3 of user pi.
Jan 18 01:19:34 raspberrypi systemd-logind[471]: New session c3 of user pi.
Jan 18 01:20:04 raspberrypi sudo[1234]: pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/journalctl -n 1000
Jan 18 01:20:04 raspberrypi sudo[1234]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Jan 18 01:22:22 raspberrypi sudo[1245]: pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/journalctl -n 1000
Jan 18 01:22:22 raspberrypi sudo[1245]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
NoelSinggih commented 7 years ago

Hi Mike,

I'm interested to know if there's any development on this as I have also been getting occasional pop noise when i switched tracks. Usually it happens at the beginning of the new track.

FYI - my setup is a Raspberry Pi3 with Volumio 2.041 (which from what I understand runs Shairport-sync), connected to a Gustard X20Pro DAC via USB, which then connected to my Micromega AS-400 and my speakers Monitor Audio PL100.

I can't seem to re-create the symptoms consistently, it doesn't always happen, but when it does, i can hear a little pop, or screech noise at the beginning of a track (from Tidal HIFI).

Thanks, Noel

mikebrady commented 7 years ago

Thanks for the post @x187lockdown. What I'm looking for is an idea of how much interpolation is occurring, and that information is available if you turn on statistics in the configuration file. In the general section, change the line:

//  statistics = "no"; // set to "yes" to print statistics in the log

to

    statistics = "yes"; // set to "yes" to print statistics in the log

Notice I removed the leading \\ to uncomment, i.e. to activate the line. Then restart and play some music. You'll see extra statistical information appearing in the log. That would be very useful to help diagnose the problem.

@NoelSinggih Hi Noel. I am guessing that your issue is different. I think Tidal may be closing down the play session and then reopening another when it moves to a new track. Something odd happens occasionally in those circumstances – it's probably a race condition that I haven't been able to track down yet. But the occasional pop or screech, possibly due to left-over samples, sometimes happens. It's frustrating, and if anyone can make it happen consistently, I'd love to check it out.

NoelSinggih commented 7 years ago

Thanks for the response Mike. I am thinking along the same line on Tidal closing the session and reopening it on the cause of the drop off. Whenever I play continuously from a playlist of songs that I've downloaded (from Tidal) I'm not experiencing this issue or it happens very infrequently.  On the pop and screech, strange as I have not been getting this again in the last couple of days or so. Still a mystery. 

Get Outlook for iOS

On Sat, Jan 21, 2017 at 5:05 PM +0800, "Mike Brady" notifications@github.com wrote:

Thanks for the post @x187lockdown. What I'm looking for is an idea of how much interpolation is occurring, and that information is available if you turn on statistics in the configuration file. In the general section, change the line: // statistics = "no"; // set to "yes" to print statistics in the log

to statistics = "yes"; // set to "yes" to print statistics in the log

Notice I removed the leading \ to uncomment, i.e. to activate the line. Then restart and play some music. You'll see extra statistical information appearing in the log. That would be very useful to help diagnose the problem.

@NoelSinggih Hi Noel. I am guessing that your issue is different. I think Tidal may be closing down the play session and then reopening another when it moves to a new track. Something odd happens occasionally in those circumstances – it's probably a race condition that I haven't been able to track down yet. But the occasional pop or screech, possibly due to left-over samples, sometimes happens. It's frustrating, and if anyone can make it happen consistently, I'd love to check it out.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

x187lockdown commented 7 years ago

Hi Mike,

Thanks for getting back, you can talk to me on a level, I'm technically fluent.

So here are the logs, I sat and listened with a clock in front of me and noted down some times I heard the issue. The noise I hear could almost be mistaken for those warm pops you hear on vinyl. Here's the times I heard it occur:

15:27:45-55 15:30:45-50 15:32:30 15:33:40 15:36:00-20 15:39:52

Jan 22 15:12:09 raspberrypi systemd[1]: Time has been changed
Jan 22 15:12:09 raspberrypi systemd[644]: Time has been changed
Jan 22 15:12:13 raspberrypi dhcpcd[483]: wlan0: no IPv6 Routers available
Jan 22 15:13:05 raspberrypi shairport-sync[560]: sync error in frames, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy
Jan 22 15:13:38 raspberrypi shairport-sync[560]: -23.1,      21.5,      21.5,        3758,      0,      0,      0,      0,   5026,  216,  234
Jan 22 15:14:08 raspberrypi shairport-sync[560]: -82.8,      90.7,      90.7,        7516,      0,      0,      0,      0,   6026,  219,  235
Jan 22 15:14:38 raspberrypi shairport-sync[560]: -29.0,      89.2,      89.2,       11274,      0,      0,      0,      0,   6025,  215,  235
Jan 22 15:15:08 raspberrypi shairport-sync[560]: -77.0,      96.8,      96.8,       15032,      0,      0,      0,      0,   5996,  219,  235
Jan 22 15:15:38 raspberrypi shairport-sync[560]: -69.2,      68.8,      68.8,       18790,      0,      0,      0,      0,   6019,  219,  235
Jan 22 15:16:08 raspberrypi shairport-sync[560]: -81.0,      99.0,      99.0,       22548,      0,      0,      0,      0,   5994,  219,  235
Jan 22 15:16:37 raspberrypi shairport-sync[560]: -37.9,      20.4,     111.1,       26306,      0,      0,      0,      0,   6013,  219,  234
Jan 22 15:17:01 raspberrypi CRON[820]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 22 15:17:01 raspberrypi CRON[827]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 22 15:17:01 raspberrypi CRON[820]: pam_unix(cron:session): session closed for user root
Jan 22 15:17:07 raspberrypi shairport-sync[560]: -81.2,     160.3,     160.3,       30064,      0,      0,      0,      0,   6002,  227,  234
Jan 22 15:17:37 raspberrypi shairport-sync[560]: -76.9,      93.7,      93.7,       33822,      0,      0,      0,      0,   6037,  217,  235
Jan 22 15:18:07 raspberrypi shairport-sync[560]: -79.3,      79.4,      79.4,       37580,      0,      0,      0,      0,   6013,  227,  235
Jan 22 15:18:37 raspberrypi shairport-sync[560]: -80.3,      93.0,      93.0,       41338,      0,      0,      0,      0,   6057,  215,  234
Jan 22 15:19:07 raspberrypi shairport-sync[560]: -34.9,      40.8,      40.8,       45096,      0,      0,      0,      0,   6032,  218,  234
Jan 22 15:19:37 raspberrypi shairport-sync[560]: -64.2,     137.6,     137.6,       48854,      0,      0,      0,      0,   5974,  218,  234
Jan 22 15:19:59 raspberrypi shairport-sync[560]: Playback Stopped. Total playing time 00:06:54
Jan 22 15:20:01 raspberrypi shairport-sync[560]: sync error in frames, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy
Jan 22 15:20:33 raspberrypi shairport-sync[560]: -51.6,      37.8,      80.2,        3758,      0,      0,      0,      0,   4282,  208,  235
Jan 22 15:21:03 raspberrypi shairport-sync[560]: -75.1,      93.7,      93.7,        7516,      0,      0,      0,      0,   6017,  227,  235
Jan 22 15:21:33 raspberrypi shairport-sync[560]: -79.8,      85.4,      85.4,       11274,      0,      0,      0,      0,   6049,  227,  235
Jan 22 15:22:03 raspberrypi shairport-sync[560]: -38.2,      83.9,     248.7,       15032,      0,      0,      0,      0,   5950,  227,  235
Jan 22 15:22:33 raspberrypi shairport-sync[560]: -73.0,      95.3,      95.3,       18790,      0,      0,      0,      0,   6054,  216,  234
Jan 22 15:23:03 raspberrypi shairport-sync[560]: -77.7,      70.3,      70.3,       22548,      0,      0,      0,      0,   6030,  227,  235
Jan 22 15:23:33 raspberrypi shairport-sync[560]: -72.6,     116.4,     116.4,       26306,      0,      0,      0,      0,   6005,  223,  235
Jan 22 15:24:03 raspberrypi shairport-sync[560]: -12.2,      80.9,     147.4,       30064,      0,      0,      0,      0,   5991,  227,  234
Jan 22 15:24:33 raspberrypi shairport-sync[560]: -76.1,      94.5,      94.5,       33822,      0,      0,      0,      0,   6033,  215,  235
Jan 22 15:25:03 raspberrypi shairport-sync[560]: -82.8,      92.2,      92.2,       37580,      0,      0,      0,      0,   5765,  217,  235
Jan 22 15:25:33 raspberrypi shairport-sync[560]: -39.5,      97.5,      97.5,       41338,      0,      0,      0,      0,   5970,  208,  235
Jan 22 15:26:03 raspberrypi shairport-sync[560]: -71.6,      60.5,      60.5,       45096,      0,      0,      0,      0,   6056,  215,  235
Jan 22 15:26:33 raspberrypi shairport-sync[560]: -73.1,     111.1,     111.1,       48854,      0,      0,      0,      0,   6026,  226,  235
Jan 22 15:26:46 raspberrypi systemd[1]: Starting Cleanup of Temporary Directories...
Jan 22 15:26:46 raspberrypi systemd[1]: Started Cleanup of Temporary Directories.
Jan 22 15:27:03 raspberrypi shairport-sync[560]: -83.0,      80.9,      80.9,       52612,      0,      0,      0,      0,   5969,  226,  235
Jan 22 15:27:33 raspberrypi shairport-sync[560]: -56.8,     120.2,     120.2,       56370,      0,      0,      0,      0,   6007,  225,  235
Jan 22 15:28:03 raspberrypi shairport-sync[560]: -38.0,      75.6,     104.3,       60128,      0,      0,      0,      0,   5965,  224,  235
Jan 22 15:28:33 raspberrypi shairport-sync[560]: -83.5,      89.2,      89.2,       63886,      0,      0,      0,      0,   6008,  224,  235
Jan 22 15:29:03 raspberrypi shairport-sync[560]: -70.1,      92.2,      92.2,       67644,      0,      0,      0,      0,   6027,  215,  235
Jan 22 15:29:33 raspberrypi shairport-sync[560]: -53.9,      80.9,      80.9,       71402,      0,      0,      0,      0,   6013,  222,  235
Jan 22 15:30:03 raspberrypi shairport-sync[560]: -59.1,      82.4,      82.4,       75160,      0,      0,      0,      0,   6056,  223,  235
Jan 22 15:30:33 raspberrypi shairport-sync[560]: -61.9,      98.3,      98.3,       78918,      0,      0,      0,      0,   6037,  225,  235
Jan 22 15:31:03 raspberrypi shairport-sync[560]: -84.5,     107.3,     107.3,       82676,      0,      0,      0,      0,   6026,  226,  235
Jan 22 15:31:33 raspberrypi shairport-sync[560]: -84.2,      85.4,      85.4,       86434,      0,      0,      0,      0,   6054,  215,  235
Jan 22 15:32:03 raspberrypi shairport-sync[560]: -83.1,      93.7,      93.7,       90192,      0,      0,      0,      0,   6050,  216,  235
Jan 22 15:32:33 raspberrypi shairport-sync[560]: -80.5,      92.2,      92.2,       93950,      0,      0,      0,      0,   6051,  227,  235
Jan 22 15:33:03 raspberrypi shairport-sync[560]: -83.7,      93.7,      93.7,       97708,      0,      0,      0,      0,   6053,  227,  235
Jan 22 15:33:33 raspberrypi shairport-sync[560]: -79.3,      92.2,      92.2,      101466,      0,      0,      0,      0,   6051,  227,  235
Jan 22 15:34:03 raspberrypi shairport-sync[560]: -66.6,      83.2,      83.2,      105224,      0,      0,      0,      0,   6054,  226,  234
Jan 22 15:34:33 raspberrypi shairport-sync[560]: -84.4,      96.0,      96.0,      108982,      0,      0,      0,      0,   6029,  226,  235
Jan 22 15:35:03 raspberrypi shairport-sync[560]: -83.9,      86.2,      86.2,      112740,      0,      0,      0,      0,   5979,  225,  235
Jan 22 15:35:33 raspberrypi shairport-sync[560]: -80.4,      91.5,      91.5,      116498,      0,      0,      0,      0,   6042,  226,  235
Jan 22 15:36:03 raspberrypi shairport-sync[560]: -65.0,      93.7,      93.7,      120256,      0,      0,      0,      0,   5976,  216,  235
Jan 22 15:36:33 raspberrypi shairport-sync[560]: -84.2,      90.7,      90.7,      124014,      0,      0,      0,      0,   5985,  227,  235
Jan 22 15:37:03 raspberrypi shairport-sync[560]: -84.2,      93.0,      93.0,      127772,      0,      0,      0,      0,   6032,  226,  235
Jan 22 15:37:33 raspberrypi shairport-sync[560]: -70.9,      81.6,      81.6,      131530,      0,      0,      0,      0,   6007,  224,  235
Jan 22 15:38:03 raspberrypi shairport-sync[560]: -84.5,     103.6,     103.6,      135288,      0,      0,      0,      0,   5989,  225,  235
Jan 22 15:38:33 raspberrypi shairport-sync[560]: -45.3,      84.7,      84.7,      139046,      0,      0,      0,      0,   6012,  225,  235
Jan 22 15:39:03 raspberrypi shairport-sync[560]: -68.0,      93.0,      93.0,      142804,      0,      0,      0,      0,   6026,  226,  235
Jan 22 15:39:32 raspberrypi shairport-sync[560]: -72.5,      63.5,      63.5,      146562,      0,      0,      0,      0,   6037,  215,  235
Jan 22 15:40:02 raspberrypi shairport-sync[560]: -72.9,     127.0,     127.0,      150320,      0,      0,      0,      0,   5993,  218,  235
Jan 22 15:40:32 raspberrypi shairport-sync[560]: -80.2,      93.0,      93.0,      154078,      0,      0,      0,      0,   6054,  225,  235
Jan 22 15:41:02 raspberrypi shairport-sync[560]: -83.0,      90.0,      90.0,      157836,      0,      0,      0,      0,   6053,  227,  235
Jan 22 15:41:32 raspberrypi shairport-sync[560]: -55.1,      83.9,      83.9,      161594,      0,      0,      0,      0,   6055,  215,  235
Jan 22 15:42:02 raspberrypi shairport-sync[560]: -34.5,      93.7,     178.4,      165352,      0,      0,      0,      0,   5959,  225,  235
Jan 22 15:42:32 raspberrypi shairport-sync[560]: -69.0,      74.8,      74.8,      169110,      0,      0,      0,      0,   5977,  223,  235
Jan 22 15:43:02 raspberrypi shairport-sync[560]: -81.9,     107.3,     107.3,      172868,      0,      0,      0,      0,   6054,  223,  234
Jan 22 15:43:32 raspberrypi shairport-sync[560]: -43.8,      93.7,      93.7,      176626,      0,      0,      0,      0,   6006,  227,  235
Jan 22 15:44:02 raspberrypi shairport-sync[560]: -59.2,      62.0,      72.6,      180384,      0,      0,      0,      0,   6054,  227,  235
Jan 22 15:44:32 raspberrypi shairport-sync[560]: -38.4,     126.2,     303.1,      184142,      0,      0,      0,      0,   5979,  226,  235
Jan 22 15:45:02 raspberrypi shairport-sync[560]: -80.1,      86.9,      86.9,      187900,      0,      0,      0,      0,   6046,  216,  235
Jan 22 15:45:32 raspberrypi shairport-sync[560]: -60.7,      94.5,      94.5,      191658,      0,      0,      0,      0,   6026,  226,  235
Jan 22 15:46:02 raspberrypi shairport-sync[560]: -38.7,      92.2,      92.2,      195416,      0,      0,      0,      0,   5961,  227,  235
Jan 22 15:46:32 raspberrypi shairport-sync[560]: -82.7,      83.2,      83.2,      199174,      0,      0,      0,      0,   6057,  225,  235
Jan 22 15:47:02 raspberrypi shairport-sync[560]: -82.2,      86.9,      86.9,      202932,      0,      0,      0,      0,   6028,  227,  235
Jan 22 15:47:32 raspberrypi shairport-sync[560]: -75.7,      99.8,      99.8,      206690,      0,      0,      0,      0,   6022,  226,  235
Jan 22 15:48:02 raspberrypi shairport-sync[560]: -11.1,      23.4,      23.4,      210448,      0,      0,      0,      0,   6057,  225,  235
Jan 22 15:48:32 raspberrypi shairport-sync[560]: -24.3,     164.0,     200.3,      214206,      0,      0,      0,      0,   5968,  224,  235
Jan 22 15:49:02 raspberrypi shairport-sync[560]: -78.6,      99.8,      99.8,      217964,      0,      0,      0,      0,   5875,  217,  235
Jan 22 15:49:32 raspberrypi shairport-sync[560]: -66.5,      85.4,      85.4,      221722,      0,      0,      0,      0,   6040,  226,  235
Jan 22 15:50:02 raspberrypi shairport-sync[560]: -54.1,      86.2,      86.2,      225480,      0,      0,      0,      0,   6006,  225,  235
Jan 22 15:50:32 raspberrypi shairport-sync[560]: -48.1,      83.9,      83.9,      229238,      0,      0,      0,      0,   5976,  224,  235
Jan 22 15:51:02 raspberrypi shairport-sync[560]: -73.4,      96.8,      96.8,      232996,      0,      0,      0,      0,   6055,  224,  235
Jan 22 15:51:32 raspberrypi shairport-sync[560]: -83.9,     102.1,     102.1,      236754,      0,      0,      0,      0,   6045,  225,  235
Jan 22 15:52:02 raspberrypi shairport-sync[560]: 9.7,    -128.5,     184.5,      240512,      0,      0,      0,      0,   6057,  224,  235
Jan 22 15:52:32 raspberrypi shairport-sync[560]: -85.9,     310.7,     312.2,      244270,      0,      0,      0,      0,   5812,  227,  235
Jan 22 15:52:37 raspberrypi sshd[868]: Accepted password for pi from 192.168.0.101 port 55937 ssh2
Jan 22 15:52:37 raspberrypi sshd[868]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Jan 22 15:52:37 raspberrypi systemd[1]: Starting Session c3 of user pi.
Jan 22 15:52:37 raspberrypi systemd-logind[471]: New session c3 of user pi.
Jan 22 15:52:37 raspberrypi systemd[1]: Started Session c3 of user pi.
Jan 22 15:52:51 raspberrypi sudo[892]: pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/journalctl -n 1000
Jan 22 15:52:51 raspberrypi sudo[892]: pam_unix(sudo:session): session opened for user root by pi(uid=0)

Does this give anymore clues? Let me know if you need anymore logs.

Thanks, Mike

mikebrady commented 7 years ago

Thanks Mike. Sorry if I was labouring the points a bit but there might be other readers who are not quite so au-fait.

Anyway, I was interested to see if there was packet loss or excessive interpolations, and I'm glad to say that there is no packet loss at all and a moderate amount of interpolation.

While the amount of interpolation is not (in my experience) excessive, it is nevertheless possible that what you are hearing is actually related to interpolation, although I can't see any special reason you should hear the artefacts when you do. So, I suggest you turn on disable_synchronization and see if the artefacts disappear. If they do, then we need to investigate further; there could be a bug in the interpolation code. If not, then we have a real puzzle on our hands!

quinnaissance commented 7 years ago

Hello Mike,

I just bought a Pi 3 for shairport-sync, set it up this morning and came on here looking for someone with this issue. I'm getting a similar crackling as described by @x187lockdown . It's not bad enough to want to stop listening, but it's noticeable enough to be quite annoying. It sounds a vinyl record player; very short, soft crackles.

It almost seems to be like some sort of audio clipping as it typically only happens on heavy bass hits or sharp, high sounds/notes. It's not my speakers, 3.5mm cable or my Pi's USB sound card, because if I play the same files through Chromium (via Plex) in Raspbian, there is no crackling.

I'm using an iPhone 6 as a source. Another weird thing I found is, using the iPhone, if I play a song through the iOS Spotify app, there is far less crackling (only on really sharp/loud spots on songs that are mastered louder -- on softer songs its gone completely). However, if I use the Apple Music app, it's there. It's also there with the Plex app. The crackling is definitely not in the file itself because it's fine on my other devices, however, obviously the file being played through the Apple Music & Plex apps are the same format (mp3), versus whatever Spotify uses (i think Ogg?). Because of this, I'm thinking this may be a transcoding issue. Perhaps the mp3's are being transcoded too loud causing some sort of clipping? Anyways, I think I should leave the assumptions to someone else, considering I have next to no programming/engineering experience.

Please let me know if you want any more information.

mikebrady commented 7 years ago

Thanks for the report. Is it possible you have the equalizer enabled or if you have soundcheck enabled in the Music app? If so, what happens if you turn them off?

mikebrady commented 7 years ago

By the way, what USB sound card are you using please?

quinnaissance commented 7 years ago

No EQ or soundcheck enabled on the phone. I'm using this Trond AC2 off Amazon.

I noticed if I turn my phone volume down by one volume button iteration (from maximum), all the distortion/crackling is completely gone (even if speaker volume is turned up to compensate). Does this mean it was the sound card to begin with? I tried turning the volume down in a similar way through the Raspbian and it didn't work; it seems phone volume is the only thing that makes a difference.

Either way, this is a good enough workaround for now. I also want to say thank you not only for the incredible piece of software but for such a quick response!

mikebrady commented 7 years ago

Thanks for the kind words. It's really hard to know what is causing the issue. At this distance, one can only speculate. Here are some thoughts and speculations.

I would have a lot more faith in the fidelity of the Apple-only processing and application chain from the original recording to the DAC than I would have in Spotify, so my guess is the Music app is "right".

As far as I know, if you import a CD into iTunes and use Apple Lossless Format, the copy is bit-faithful to the original. By experiment, I know that if you then send an Apple Lossless track from iTunes to Shairport Sync (with all special effects and equalization off), it arrives bit-faithful to the original uncompressed track. This is by experiment; I can't prove that the received track is always bit faithful, but each time I've checked it, it have been. The material you have referred to is encoded in MP3 or similar lossy (i.e. low fidelity) format. If you could source some losslessly-encoded tracks and get them onto your phone, that would eliminate compression artefacts as a possible cause.

I have some USB cards based on the same chipset as the one you refer to, and I don't imagine the digital part of them is defective. So, if the problem is not the material, I'd be guessing there might be a problem in the analog chain – either the output drivers of the DAC are not up to the job, or the output of the DAC is high enough on Apple-sourced material to overload the input circuitry of your stereo.

One way of finding out more would be to listen to the output, playing lossless or losslessly-encoded material on a different device. For example, instead of the stereo, listen on good-quality headphones and see if the distortion is present.

Anyway, it's a bit of work, but might be rewarding.

cklokmose commented 6 years ago

I've had the same issue. I typically stream music from Spotify on a Mac to shairport-sync running on my Raspberry Pi 3 with a HifiBerry Digi+ harness and a toslink connection to a high-end DAC. I was experiencing similar occasional popping noises, but ignore_volume_control = "yes"; seems to have fixed the the problem for me.

mikebrady commented 6 years ago

Hmm, that's interesting. Does the HifiBerry Digi+ have a hardware mixer, and were you using it?

cklokmose commented 6 years ago

Not that I am aware of, no.

cklokmose commented 6 years ago

Apologies for reviving this issue. With a bit more time for listening the ignore_volue_control = "yes"; didn't seem to solve the issue. I tried to see if I could record the distortion with my phone, and it was actually picked up surprisingly well. The recording can be heard here On the recording the noise is quite prominent, but in normal listening it is barely noticeable. Enabling soxr doesn't seem to change anything.

The music is streamed from Spotify. If I stream to my Apple TV that is connected to the same amplifier through optical over the TV, the noise is not present.

The configuration used here is the default one with only the name of the receiver changed.

elliotjberman commented 6 years ago

+1

mikebrady commented 6 years ago

Thanks for the posts. Can you say what version of Shairport Sync? You can find out using the command shairport-sync -V.

cklokmose commented 6 years ago

Output from shairport-sync -V: 3.2RC12-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc

elliotjberman commented 6 years ago

Output: 3.2RC12-OpenSSL-Avahi-ALSA-metadata-sysconfdir:/usr/local/etc

mikebrady commented 6 years ago

Thanks to both of you. I played that recording and I can hear the sound quite distinctly. It sounds like a high level of interpolation, i.e. a lot of stuffing is going on. So, to investigate further, two possibilities present themselves: 1 There is an alsa setting to enable you to disable interpolation, called disable_synchronization. Set it to "yes" (remember to uncomment it!) and restart Shairport Sync to see if the noise goes away. 2 Separately, having re-enabled interpolation, could you turn on the logging of statistics please? This would log the amount of interpolation that's being done and it would be great if you posted the stats here.

cklokmose commented 6 years ago

Hi again,

Enabling disable_synchronization removed the noise. Is this a viable solution? What are the effects of this?

Here's the log of 45 seconds of the song I recorded yesterday with disable_synchronization off: statistics.log

mikebrady commented 6 years ago

Thanks. This is good stuff. The key discovery is that there is a great deal of overcorrection happening, causing a great deal of unnecessary stuffing which is becoming audible. If you look at one entry:

      -0.1,     274.7,    1668.3,        2006,      0,      0,      0,      0,   5988,  226,  231

you'll see that the net correction needed for synchronisation is 274.7 parts per million, but due to over-correction, the amount of correction actually applied was 1668.3 parts per million, approximately five times more than needed. One way to combat this is to widen the drift tolerance. The default is 0.002 seconds, 2 milliseconds, but if you make it 0.010 seconds, 10 milliseconds, see how much correction is applied. Ideally it should match what is needed exactly. The setting is drift_tolerance_in_seconds.

Once you get the overcompensation under control, the distortion should be much less audible.

Disabling synchronisation is not a viable alternative, as it means that sooner or later a buffer will overflow or underflow somewhere and the audio programme will be interrupted. Your network isn't dropping any audio packets, so that's fine.

However, the numbers remain concerning, because they indicate two troubling things.

First, the net corrections figure is very high -- I'd expect it to be below 150, and if the source is a modern iOS device it should be well below 50. Typically, from an iPhone 6 to a Raspberry Pi running an I2S DAC the drift would be around 25 ppm. So, some questions are: what is your source? Is it Spotify running on a Mac? What happens if the source is an iOS device or iTunes on a Mac?

The second observation is that the very high level of overcorrection for a 2 millisecond tolerance tends to indicate that the audio packets are being received at intervals that vary very widely. The cause may be that they are sent irregularly, or that the DAC driver means that they are being received irregularly. I have noticed that if the DAC is the Pi's built-in DAC, the tolerance needs to be set to around 8 ms, but if the DAC is a Pimoroni PHAT, for example, the 2 ms tolerance is fine.

cklokmose commented 6 years ago

Hi Mike,

Thanks for the detailed response! I have a Mac (10.13.4) running Spotify (1.0.82.447.g975ad224) through Airfoil (5.7.4). I use Airfoil to be able to play in multiple rooms from Spotify. I tried to bypass Airfoil and run directly from Spotify over Airplay from the Mac. The noise/distortion was far less, but there was still slight audible popping. I bought the same song on iTunes and tried it through iTunes with Airfoil => lots of distortion, without Airfoil => less distortion. Now I tried playing the same song from Spotify and iTunes from my iPhone 8 => no distortion.

So it seems that Airfoil causes a lot of the problems, but the distortion is still present to some degree when playing directly from the Mac.

I've compiled the statistics in the attached file. Its 45 seconds of the same song in the different conditions.

Devices.txt

mikebrady commented 6 years ago

Thanks for the logs. Yes indeed, it seems that the overcompensation can be explained by the use of Airfoil. If you make the drift tolerance larger, e.g. 0.010 seconds, that will help with that problem.

However, there does seem to be an underlying divergence in timing of 100 to 150 parts per million, even with the source being an iPhone. To see if the divergence might be due the HifiBerry Digi+, try (temporarily) redirecting the output to the Pi3's built-in DAC and see if the divergence persists. AFAIK, the clock rate of the built-in DAC is tied to the Pi's own clock, whereas the Digi+ may have its own clock.

cklokmose commented 6 years ago

Thanks again, Mike!

I had to push the drift tolerance to 0.015 to get rid of the distortion. I've attached statistics for 0.012 (where it distorts) and 0.015 with Spotify over Airfoil. Now there's no continuous distortion with 0.015, but some pops now and then.

When I have a bit more time I will test the internal DAC of the Pi.

Drift.txt

mumrah commented 6 years ago

I have tried the following:

And I still get very loud pops.

My environment:

I'm happy to try different settings out, supply logs, etc. Thanks!

mikebrady commented 6 years ago

Thanks for the post. You should update to the latest Shairport Sync (not sharepoint-sync BTW). Version 2.8.6 is pretty ancient.

mumrah commented 6 years ago

Thanks, I'll try updating. Sorry, "sharepoint" is hard coded deep in my muscle memory 😩

mumrah commented 6 years ago

Ok, built and installed 3.2.1 and the pops are mostly gone! When playing from Pandora on my phone, I get one pop when first connecting, but no longer get pops between songs. However, when playing from pianobar on my laptop, I get pops before every song plays (I suspect this is probably pianobar's fault, which has other audio issues).

BTW, when following the instructions in the README.md, I get the following error when trying to setup the systemd:

$ sudo systemctl enable shairport-sync
Synchronizing state of shairport-sync.service with SysV service script with /lib/systemd/systemd-sysv-install.
Executing: /lib/systemd/systemd-sysv-install enable shairport-sync
Failed to enable unit: Unit file /etc/systemd/system/shairport-sync.service is masked.

I previously had shairport-sync installed via apt-get.

mikebrady commented 6 years ago

That's good new on the pops front. My guess about the remaining pops is that they occur when the DAC is turned on at the start of a play session, and that in the case of Pandora, a play session begins at the start of listening and continues until you stop, whereas in the case of Pianobar, each song is a separate play session. This (very slight) click or pop can be heard with the Pimoroni pHAT and also with the Pi's built-in DAC. I have found that it can be lessened if you choose 32-bit or 24-bit sound output (assuming the output device is capable of it).

Regarding the systemd error -- it's not something I've encountered; maybe someone else can shed light on it.

mumrah commented 6 years ago

Ok, resolved the systemd error. Apparently when apt-get remove shairport-sync a file is left over (/etc/systemd/system/shairport-sync.service). Removing it and re-running the systemctl command fixes things.

mikebrady commented 6 years ago

That’s useful, thanks.

mikebrady commented 5 years ago

Hi there. We've been doing some related work that might make a difference, if you're still interested. Please see here.

mikebrady commented 4 years ago

Closing the issue – please open a new one if necessary.