HDMI CEC struggles & wireless network performance on new Vero 4K+

jaybird · 4 July 2019 12:48

Switching the test target to a UFS datastore does not yield notable variation:

dd read of test file on UFS volume initiated directly on NAS:

tardis: test# dd if=test.file of=/dev/null bs=1M
4096+0 records in
4096+0 records out
4294967296 bytes transferred in 37.051260 secs (115919600 bytes/sec)

dd read from Vero:

osmc@osmc:/mnt/test$ dd if=test.file of=/dev/null bs=1M
4096+0 records in
4096+0 records out
4294967296 bytes (4.3 GB, 4.0 GiB) copied, 209.627 s, 20.5 MB/s

dd read from Vero (disabled kernel tuning in NAS, which can sometimes cause negative performance oddities):

osmc@osmc:/mnt/test$ dd if=test.file of=/dev/null bs=1M
4096+0 records in
4096+0 records out
4294967296 bytes (4.3 GB, 4.0 GiB) copied, 240.677 s, 17.8 MB/s

NFS stats for all the testing session above.

osmc@osmc:/mnt/Media$ nfsstat
Server rpc stats:
calls      badcalls   badfmt     badauth    badclnt
0          0          0          0          0       

Client rpc stats:
calls      retrans    authrefrsh
197576     0          197576  

Client nfs v3:
null             getattr          setattr          lookup           access           
0         0%     504       0%     0         0%     9         0%     507       0%     
readlink         read             write            create           mkdir            
0         0%     196031   99%     0         0%     0         0%     1         0%     
symlink          mknod            remove           rmdir            rename           
0         0%     0         0%     0         0%     0         0%     0         0%     
link             readdir          readdirplus      fsstat           fsinfo           
0         0%     0         0%     493       0%     4         0%     8         0%     
pathconf         commit           
4         0%     0         0%

Just for curiosity sake, I’ve tried mounting the share as NFSv4, but it yield no perceivable increase in performance.

Testing it with a macOS (10.14.5) built-in NFS server (with test file hosted on an SSD) resulted in similar peaky, if not a bit slower results (could be due to rsize/wsize being limited to 64k):

osmc@osmc:/mnt/Media$ dd if=test.file of=/dev/null bs=1M
4096+0 records in
4096+0 records out
4294967296 bytes (4.3 GB, 4.0 GiB) copied, 253.471 s, 16.9 MB/s

This sounds to me like an issue with NFS optimisation over wireless LAN.

There are some interesting articles from what I can find in relation to NFS over WLAN, a particularly old one with interesting read - Measuring NFS performance in wireless networks | Semantic Scholar

jaybird · 4 July 2019 12:56

Had a look through what your threads, it all sounds very familiar!

If you’re keen, there’s a wealth of information (and noise) from the libCEC logs or when you try to monitor the session using the cec-client.

dillthedog · 4 July 2019 19:18

I assume this is between the V4K+ and macOS device. You don’t say if the Apple device is wired, but that would again be my assumption. If it’s a laptop, you should also try it as a wireless NFS client (via the same AP) to see how it performs.

jaybird · 4 July 2019 22:07

   Vero 4K+ <> UniFi nanoHD AP <> HP GigE switch <> Mac mini
MacBook Pro <>                                   <> NAS

You assume correct, the macOS device is physically connected to the same GigE switch as the NAS.

I’ve done some quick initial testing using another MacBook Pro, results seems to be similar compared to the Vero and the NAS - it appears to have a similar throughput discrepancy between iperf3 and NFS tests.

I’ve got a bit more testing to do but will upload some results when done.

sam_nazarko · 4 July 2019 22:16

Back to CEC, I’ve pushed some changes today.

To test this update:

Login via the command line
Edit the file /etc/apt/sources.list
Add the following line: deb http://apt.osmc.tv stretch-devel main
Run the following commands to update: sudo apt-get update && sudo apt-get dist-upgrade && reboot
Your system should have have received the update.

Please see if the issue is resolved.

I also recommend you edit /etc/apt/sources.list again and remove the line that you added after updating. This will return you to the normal update channel.

jaybird · 5 July 2019 07:44

Hi @sam_nazarko ,

Thank you for this, for a second I thought it worked but alas, the CEC issue appears to be persisting.

Here’s the output from libCEC, hopefully it may help?

### Unit freshly restarted 

osmc@osmc:~$ cec-client AOCEC
No device type given. Using 'recording device'
CEC Parser created - libCEC version 4.0.4
opening a connection to the CEC adapter...
DEBUG:   [               1]	Broadcast (F): osd name set to 'Broadcast'
NOTICE:  [               1]	connection opened
DEBUG:   [               1]	processor thread started
DEBUG:   [               1]	<< Broadcast (F) -> TV (0): POLL
TRAFFIC: [               1]	<< f0
DEBUG:   [              71]	>> POLL sent
DEBUG:   [              71]	TV (0): device status changed into 'present'
DEBUG:   [              71]	<< requesting vendor ID of 'TV' (0)
TRAFFIC: [              71]	<< f0:8c
TRAFFIC: [             281]	>> 0f:87:00:80:45
DEBUG:   [             281]	TV (0): vendor = Panasonic (008045)
DEBUG:   [             281]	>> TV (0) -> Broadcast (F): device vendor id (87)
DEBUG:   [             281]	expected response received (87: device vendor id)
DEBUG:   [             281]	replacing the command handler for device 'TV' (0)
NOTICE:  [             281]	registering new CEC client - v4.0.4
DEBUG:   [             281]	detecting logical address for type 'playback device'
DEBUG:   [             281]	trying logical address 'Playback 1'
DEBUG:   [             281]	<< Playback 1 (4) -> Playback 1 (4): POLL
TRAFFIC: [             281]	<< 44
DEBUG:   [             361]	>> POLL sent
DEBUG:   [             361]	logical address 'Playback 1' already taken
DEBUG:   [             361]	Playback 1 (4): device status changed into 'present'
DEBUG:   [             361]	trying logical address 'Playback 2'
DEBUG:   [             361]	<< Playback 2 (8) -> Playback 2 (8): POLL
TRAFFIC: [             361]	<< 88
WARNING: [             561]	Write: write failed
TRAFFIC: [             561]	<< 88
WARNING: [             761]	Write: write failed
DEBUG:   [             761]	>> POLL not sent
DEBUG:   [             761]	using logical address 'Playback 2'
DEBUG:   [             761]	Playback 2 (8): device status changed into 'handled by libCEC'
DEBUG:   [             761]	Playback 2 (8): power status changed from 'unknown' to 'on'
DEBUG:   [             761]	Playback 2 (8): vendor = Pulse Eight (001582)
DEBUG:   [             761]	Playback 2 (8): CEC version 1.4
DEBUG:   [             761]	AllocateLogicalAddresses - device '0', type 'playback device', LA '8'
DEBUG:   [             762]	Playback 2 (8): osd name set to 'CECTester'
DEBUG:   [             762]	Playback 2 (8): menu language set to 'eng'
DEBUG:   [             762]	AutodetectPhysicalAddress - autodetected physical address '2200'
DEBUG:   [             762]	Playback 2 (8): physical address changed from ffff to 2200
DEBUG:   [             762]	<< Playback 2 (8) -> broadcast (F): physical address 2200
TRAFFIC: [             762]	<< 8f:84:22:00:04
NOTICE:  [             921]	CEC client registered: libCEC version = 4.0.4, client version = 4.0.4, firmware version = 5, logical address(es) = Playback 2 (8) , physical address: 2.2.0.0,  compiled on Thu Jul  4 10:56:21 UTC 2019 by root@compiler2 on Linux 4.9.0-3-amd64 (armv7l), features: P8_USB, DRM, P8_detect, AOCEC
DEBUG:   [             921]	Playback 2 (8): vendor = Panasonic (008045)
DEBUG:   [             921]	replacing the command handler for device 'Playback 2' (8)
DEBUG:   [             921]	<< Playback 2 (8) -> TV (0): OSD name 'CECTester'
TRAFFIC: [             921]	<< 80:47:43:45:43:54:65:73:74:65:72
DEBUG:   [            1231]	<< requesting power status of 'TV' (0)
TRAFFIC: [            1231]	<< 80:8f
TRAFFIC: [            1431]	>> 08:00:47:00
DEBUG:   [            1431]	marking opcode 'set osd name' as unsupported feature for device 'TV'
DEBUG:   [            1431]	>> TV (0) -> Playback 2 (8): feature abort ( 0)
TRAFFIC: [            1927]	>> 08:89:10:01:05
DEBUG:   [            1927]	>> TV (0) -> Playback 2 (8): vendor command (89)
DEBUG:   [            2431]	expected response not received (90: report power status)
TRAFFIC: [            2431]	<< 80:8f
TRAFFIC: [            2640]	>> 08:89:10:01:05
DEBUG:   [            2640]	>> TV (0) -> Playback 2 (8): vendor command (89)
DEBUG:   [            3521]	expected response not received (90: report power status)
waiting for input
TRAFFIC: [            3687]	>> 08:89:10:01:05
DEBUG:   [            3687]	>> TV (0) -> Playback 2 (8): vendor command (89)
TRAFFIC: [            6128]	>> 08:a0:00:80:45:06:05
DEBUG:   [            6128]	TV (0): power status changed from 'unknown' to 'on'
DEBUG:   [            6128]	>> TV (0) -> Playback 2 (8): vendor command with id (A0)

### Unit idling on home screen. 
### Putting devices to sleep using TV remote. 

TRAFFIC: [           34240]	>> 0f:a0:00:80:45:20:01:11
DEBUG:   [           34240]	TV (0): power status changed from 'on' to 'standby'
DEBUG:   [           34240]	>> TV (0) -> Broadcast (F): vendor command with id (A0)
TRAFFIC: [           34628]	>> 5f:72:00
DEBUG:   [           34628]	>> Audio (5): system audio mode status changed from on to off
DEBUG:   [           34628]	device Audio (5) status changed to present after command set system audio mode
DEBUG:   [           34628]	>> Audio (5) -> Broadcast (F): set system audio mode (72)
TRAFFIC: [           34937]	>> 0f:36
DEBUG:   [           34937]	>> TV (0) -> Broadcast (F): standby (36)
TRAFFIC: [           35981]	>> 4f:a6:06:10:56:10
DEBUG:   [           35981]	>> Playback 1 (4) -> Broadcast (F): UNKNOWN (A6)
TRAFFIC: [           36201]	>> 4f:85
DEBUG:   [           36202]	>> 4 requests active source
DEBUG:   [           36202]	Playback 1 (4): power status changed from 'unknown' to 'on'
DEBUG:   [           36202]	<< Playback 2 (8) is not the active source
DEBUG:   [           36202]	>> Playback 1 (4) -> Broadcast (F): request active source (85)
TRAFFIC: [           36819]	>> 5f:87:00:00:f0
DEBUG:   [           36819]	Audio (5): vendor = Samsung (0000f0)
DEBUG:   [           36820]	replacing the command handler for device 'Audio' (5)
DEBUG:   [           36820]	>> Audio (5) -> Broadcast (F): device vendor id (87)
TRAFFIC: [           37207]	>> 5f:84:20:00:05
DEBUG:   [           37207]	Audio (5): physical address changed from ffff to 2000
DEBUG:   [           37207]	>> Audio (5) -> Broadcast (F): report physical address (84)

### Devices remains asleep. 
### Waking devices up using OSMC remote from suspend/standby. 

TRAFFIC: [           92768]	>> 08:90:02
DEBUG:   [           92768]	TV (0): power status changed from 'standby' to 'in transition from standby to on'
DEBUG:   [           92768]	>> TV (0) -> Playback 2 (8): report power status (90)
TRAFFIC: [           93815]	>> 0f:a0:00:80:45:20:00:01
DEBUG:   [           93815]	TV (0): power status changed from 'in transition from standby to on' to 'on'
TRAFFIC: [           93815]	<< 80:89:10:02:ff:ff:00:05:05:45:55:5c:58:32
DEBUG:   [           93815]	>> TV (0) -> Broadcast (F): vendor command with id (A0)
TRAFFIC: [           94783]	>> 5f:72:01
DEBUG:   [           94783]	>> Audio (5): system audio mode status changed from off to on
DEBUG:   [           94783]	>> Audio (5) -> Broadcast (F): set system audio mode (72)
TRAFFIC: [           96622]	>> 5f:80:20:00:22:00
DEBUG:   [           96622]	Audio (5): power status changed from 'unknown' to 'on'
DEBUG:   [           96622]	making Playback 2 (8) the active source
NOTICE:  [           96622]	>> source activated: Playback 2 (8)
DEBUG:   [           96622]	sending active source message for 'Playback 2'
TRAFFIC: [           96622]	<< 80:89:10:02:ff:ff:00:05:05:45:55:5c:58:32
DEBUG:   [           96625]	>> Audio (5) -> Broadcast (F): routing change (80)
NOTICE:  [           97021]	<< powering on 'TV' (0)
TRAFFIC: [           97021]	<< 80:04
NOTICE:  [           97301]	<< Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [           97301]	<< 8f:82:22:00
DEBUG:   [           98281]	<< Playback 2 (8) -> TV (0): menu state 'activated'
TRAFFIC: [           98281]	<< 80:8e:00
TRAFFIC: [           99291]	>> 5f:72:01
TRAFFIC: [           99291]	>> af
DEBUG:   [           99291]	>> Audio (5) -> Broadcast (F): set system audio mode (72)
TRAFFIC: [          100637]	>> 5f:84:20:00:05
DEBUG:   [          100638]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          101319]	>> 5f:84:20:00:05
DEBUG:   [          101319]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          101671]	>> 08:90:00
DEBUG:   [          101671]	>> TV (0) -> Playback 2 (8): report power status (90)
TRAFFIC: [          102054]	>> 0f:84:00:00:00
DEBUG:   [          102054]	<< Playback 2 (8) -> broadcast (F): physical address 2200
TRAFFIC: [          102054]	<< 8f:84:22:00:04
DEBUG:   [          102054]	>> TV (0) -> Broadcast (F): report physical address (84)
TRAFFIC: [          102945]	>> 5f:87:00:00:f0
DEBUG:   [          102945]	>> Audio (5) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          103516]	>> 4f:84:21:00:04
DEBUG:   [          103516]	Playback 1 (4): physical address changed from ffff to 2100
DEBUG:   [          103516]	>> Playback 1 (4) -> Broadcast (F): report physical address (84)
TRAFFIC: [          103877]	>> 4f:90:01
DEBUG:   [          103877]	Playback 1 (4): power status changed from 'on' to 'standby'
DEBUG:   [          103877]	>> Playback 1 (4) -> Broadcast (F): report power status (90)
TRAFFIC: [          104150]	>> 0f:32:65:6e:67
DEBUG:   [          104150]	TV (0): menu language set to 'eng'
DEBUG:   [          104151]	>> TV (0) -> Broadcast (F): set menu language (32)
TRAFFIC: [          105557]	>> 0f:87:00:80:45
DEBUG:   [          105557]	<< Playback 2 (8) -> Broadcast (F): vendor id Panasonic (8045)
TRAFFIC: [          105557]	<< 8f:87:00:80:45
DEBUG:   [          105557]	>> TV (0) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          106582]	>> 0f:32:65:6e:67
DEBUG:   [          106582]	>> TV (0) -> Broadcast (F): set menu language (32)
TRAFFIC: [          107682]	>> 0f:87:00:80:45
DEBUG:   [          107682]	<< Playback 2 (8) -> Broadcast (F): vendor id Panasonic (8045)
TRAFFIC: [          107682]	<< 8f:87:00:80:45
DEBUG:   [          107682]	>> TV (0) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          107942]	>> 08:90:00
DEBUG:   [          107943]	>> TV (0) -> Playback 2 (8): report power status (90)
TRAFFIC: [          109144]	>> 08:89:10:01:05
TRAFFIC: [          109144]	<< 80:89:10:02:ff:ff:00:05:05:45:55:5c:58:32
DEBUG:   [          109144]	>> TV (0) -> Playback 2 (8): vendor command (89)
DEBUG:   [          109541]	Playback 2 (8) was already marked as active source
NOTICE:  [          109541]	>> source activated: Playback 2 (8)
DEBUG:   [          109541]	scheduling active source message for 'Playback 2'
NOTICE:  [          110541]	<< powering on 'TV' (0)
TRAFFIC: [          110541]	<< 80:04
NOTICE:  [          110631]	<< Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [          110631]	<< 8f:82:22:00
DEBUG:   [          110941]	<< Playback 2 (8) -> TV (0): menu state 'activated'
TRAFFIC: [          110941]	<< 80:8e:00
TRAFFIC: [          111676]	>> 08:a0:00:80:45:06:05
NOTICE:  [          111676]	<< Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [          111676]	<< 8f:82:22:00
DEBUG:   [          111676]	>> TV (0) -> Playback 2 (8): vendor command with id (A0)
TRAFFIC: [          113220]	>> 5f:87:00:00:f0
DEBUG:   [          113221]	>> Audio (5) -> Broadcast (F): device vendor id (87)

### Putting device to sleep using TV remote, all equipment goes to sleep but wakes up immediately 

TRAFFIC: [          141488]	>> 0f:a0:00:80:45:20:01:11
DEBUG:   [          141488]	TV (0): power status changed from 'on' to 'standby'
DEBUG:   [          141488]	>> TV (0) -> Broadcast (F): vendor command with id (A0)
TRAFFIC: [          141862]	>> 5f:72:00
DEBUG:   [          141862]	>> Audio (5): system audio mode status changed from on to off
DEBUG:   [          141862]	>> Audio (5) -> Broadcast (F): set system audio mode (72)
TRAFFIC: [          142175]	>> 0f:36
DEBUG:   [          142176]	>> TV (0) -> Broadcast (F): standby (36)
TRAFFIC: [          143228]	>> 4f:a6:06:10:56:10
DEBUG:   [          143229]	>> Playback 1 (4) -> Broadcast (F): UNKNOWN (A6)
TRAFFIC: [          143451]	>> 4f:85
DEBUG:   [          143451]	>> 4 requests active source
DEBUG:   [          143451]	Playback 1 (4): power status changed from 'standby' to 'on'
NOTICE:  [          143451]	<< Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [          143451]	<< 8f:82:22:00
DEBUG:   [          143451]	>> Playback 1 (4) -> Broadcast (F): request active source (85)
TRAFFIC: [          144245]	>> 5f:87:00:00:f0
DEBUG:   [          144246]	>> Audio (5) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          145443]	>> 5f:87:00:00:f0
DEBUG:   [          145444]	>> Audio (5) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          145811]	>> 4f:a6:06:10:56:10
DEBUG:   [          145812]	>> Playback 1 (4) -> Broadcast (F): UNKNOWN (A6)
TRAFFIC: [          146207]	>> 4f:84:21:00:04
DEBUG:   [          146207]	>> Playback 1 (4) -> Broadcast (F): report physical address (84)
TRAFFIC: [          146417]	>> 5f:72:01
DEBUG:   [          146417]	>> Audio (5): system audio mode status changed from off to on
DEBUG:   [          146418]	>> Audio (5) -> Broadcast (F): set system audio mode (72)
TRAFFIC: [          147469]	>> 4f:a6:06:10:56:10
DEBUG:   [          147469]	>> Playback 1 (4) -> Broadcast (F): UNKNOWN (A6)
TRAFFIC: [          147996]	>> 4f:85
DEBUG:   [          147996]	>> 4 requests active source
NOTICE:  [          147996]	<< Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [          147996]	<< 8f:82:22:00
DEBUG:   [          147998]	>> Playback 1 (4) -> Broadcast (F): request active source (85)
TRAFFIC: [          148741]	>> 5f:84:20:00:05
DEBUG:   [          148741]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          149074]	>> 5f:84:20:00:05
DEBUG:   [          149074]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          150262]	>> 0f:87:00:80:45
DEBUG:   [          150262]	<< Playback 2 (8) -> Broadcast (F): vendor id Panasonic (8045)
TRAFFIC: [          150262]	<< 8f:87:00:80:45
DEBUG:   [          150264]	>> TV (0) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          151318]	>> 0f:a0:00:80:45:20:00:01
DEBUG:   [          151318]	TV (0): power status changed from 'standby' to 'on'
TRAFFIC: [          151318]	<< 80:89:10:02:ff:ff:00:05:05:45:55:5c:58:32
DEBUG:   [          151318]	>> TV (0) -> Broadcast (F): vendor command with id (A0)
NOTICE:  [          151781]	<< Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [          151781]	<< 8f:82:22:00
TRAFFIC: [          152477]	>> 5f:72:01
DEBUG:   [          152477]	>> Audio (5) -> Broadcast (F): set system audio mode (72)
TRAFFIC: [          152845]	>> 5f:87:00:00:f0
DEBUG:   [          152846]	>> Audio (5) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          153644]	>> 5f:84:20:00:05
DEBUG:   [          153644]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          154312]	>> 5f:84:20:00:05
DEBUG:   [          154312]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          155320]	>> 5f:87:00:00:f0
DEBUG:   [          155320]	>> Audio (5) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          155539]	>> 4f:90:01
DEBUG:   [          155539]	Playback 1 (4): power status changed from 'on' to 'standby'
DEBUG:   [          155540]	>> Playback 1 (4) -> Broadcast (F): report power status (90)
TRAFFIC: [          155889]	>> 5f:84:20:00:05
DEBUG:   [          155889]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          156944]	>> 5f:84:20:00:05
DEBUG:   [          156944]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          159212]	>> 5f:87:00:00:f0
DEBUG:   [          159212]	>> Audio (5) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          159991]	>> 0f:87:00:80:45
DEBUG:   [          159991]	<< Playback 2 (8) -> Broadcast (F): vendor id Panasonic (8045)
TRAFFIC: [          159991]	<< 8f:87:00:80:45
DEBUG:   [          159993]	>> TV (0) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          161083]	>> 5f:84:20:00:05
DEBUG:   [          161083]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          161843]	>> 4f:a6:06:10:56:10
DEBUG:   [          161843]	>> Playback 1 (4) -> Broadcast (F): UNKNOWN (A6)
TRAFFIC: [          161984]	>> 5f:84:20:00:05
DEBUG:   [          161984]	>> Audio (5) -> Broadcast (F): report physical address (84)
TRAFFIC: [          162186]	>> 08:8c
DEBUG:   [          162186]	<< Playback 2 (8) -> TV (0): vendor id Panasonic (8045)
TRAFFIC: [          162186]	<< 8f:87:00:80:45
DEBUG:   [          162186]	>> TV (0) -> Playback 2 (8): give device vendor id (8C)
TRAFFIC: [          162935]	>> 4f:90:01
DEBUG:   [          162935]	>> Playback 1 (4) -> Broadcast (F): report power status (90)
TRAFFIC: [          164270]	>> 5f:87:00:00:f0
DEBUG:   [          164270]	>> Audio (5) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          164980]	>> 0f:87:00:80:45
DEBUG:   [          164980]	<< Playback 2 (8) -> Broadcast (F): vendor id Panasonic (8045)
TRAFFIC: [          164981]	<< 8f:87:00:80:45
DEBUG:   [          164982]	>> TV (0) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          166061]	>> 0f:87:00:80:45
DEBUG:   [          166061]	<< Playback 2 (8) -> Broadcast (F): vendor id Panasonic (8045)
TRAFFIC: [          166061]	<< 8f:87:00:80:45
DEBUG:   [          166062]	>> TV (0) -> Broadcast (F): device vendor id (87)
TRAFFIC: [          168340]	>> 08:8c
DEBUG:   [          168340]	<< Playback 2 (8) -> TV (0): vendor id Panasonic (8045)
TRAFFIC: [          168340]	<< 8f:87:00:80:45
DEBUG:   [          168341]	>> TV (0) -> Playback 2 (8): give device vendor id (8C)
TRAFFIC: [          170635]	>> 08:a0:00:80:45:06:05
NOTICE:  [          170635]	<< Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [          170635]	<< 8f:82:22:00
DEBUG:   [          170635]	>> TV (0) -> Playback 2 (8): vendor command with id (A0)
TRAFFIC: [          172171]	>> 08:a0:00:80:45:06:05
NOTICE:  [          172171]	<< Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [          172171]	<< 8f:82:22:00
DEBUG:   [          172171]	>> TV (0) -> Playback 2 (8): vendor command with id (A0)

Here are the device scan using cec-client:

Fairly certain that the Vero box is device #8 “Playback 2”, I’ve not seen device #1 “Recorder 1” before though, that seems to be new…

scan
requesting CEC bus information ...
DEBUG:   [           46733]	<< requesting active source
TRAFFIC: [           46733]	<< 8f:85
DEBUG:   [           47821]	expected response not received (82: active source)
TRAFFIC: [           47821]	<< 8f:85
DEBUG:   [           48911]	expected response not received (82: active source)
DEBUG:   [           48911]	<< requesting power status of 'TV' (0)
TRAFFIC: [           48911]	<< 80:8f
DEBUG:   [           49001]	expected response received (90: report power status)
DEBUG:   [           49001]	<< requesting vendor ID of 'Recorder 1' (1)
TRAFFIC: [           49001]	<< 81:8c
WARNING: [           49251]	Write: write failed
TRAFFIC: [           49251]	<< 81:8c
WARNING: [           49431]	Write: write failed
DEBUG:   [           49431]	<< requesting physical address of 'Recorder 1' (1)
TRAFFIC: [           49431]	<< 81:83
WARNING: [           49611]	Write: write failed
TRAFFIC: [           49611]	<< 81:83
WARNING: [           49791]	Write: write failed
ERROR:   [           49791]	failed to request the physical address
DEBUG:   [           49791]	<< requesting CEC version of 'Recorder 1' (1)
TRAFFIC: [           49791]	<< 81:9f
WARNING: [           49971]	Write: write failed
TRAFFIC: [           49971]	<< 81:9f
WARNING: [           50151]	Write: write failed
DEBUG:   [           50151]	<< requesting power status of 'Recorder 1' (1)
TRAFFIC: [           50151]	<< 81:8f
WARNING: [           50331]	Write: write failed
TRAFFIC: [           50331]	<< 81:8f
WARNING: [           50511]	Write: write failed
DEBUG:   [           50511]	<< requesting OSD name of 'Recorder 1' (1)
TRAFFIC: [           50511]	<< 81:46
WARNING: [           50691]	Write: write failed
TRAFFIC: [           50691]	<< 81:46
WARNING: [           50871]	Write: write failed
DEBUG:   [           50871]	<< requesting menu language of 'Recorder 1' (1)
TRAFFIC: [           50871]	<< 81:91
WARNING: [           51051]	Write: write failed
TRAFFIC: [           51051]	<< 81:91
WARNING: [           51231]	Write: write failed
DEBUG:   [           51231]	<< requesting power status of 'Playback 1' (4)
TRAFFIC: [           51231]	<< 84:8f
DEBUG:   [           51321]	expected response received (90: report power status)
DEBUG:   [           51321]	'get menu language' is marked as unsupported feature for device 'Playback 1'
DEBUG:   [           51321]	<< requesting power status of 'Audio' (5)
TRAFFIC: [           51321]	<< 85:8f
TRAFFIC: [           51538]	>> 58:90:00
DEBUG:   [           51538]	Audio (5): power status changed from 'unknown' to 'on'
DEBUG:   [           51538]	>> Audio (5) -> Playback 2 (8): report power status (90)
DEBUG:   [           51538]	expected response received (90: report power status)
DEBUG:   [           51538]	<< requesting menu language of 'Audio' (5)
TRAFFIC: [           51538]	<< 85:91
DEBUG:   [           52641]	expected response not received (32: set menu language)
TRAFFIC: [           52641]	<< 85:91
DEBUG:   [           53731]	expected response not received (32: set menu language)
DEBUG:   [           53731]	<< requesting active source
TRAFFIC: [           53731]	<< 8f:85
DEBUG:   [           54821]	expected response not received (82: active source)
TRAFFIC: [           54821]	<< 8f:85
CEC bus information
===================
device #0: TV
address:       0.0.0.0
active source: no
vendor:        Panasonic
osd string:    TV
CEC version:   1.4
power status:  on
language:      eng


device #1: Recorder 1
address:       f.f.f.f
active source: no
vendor:        Unknown
osd string:    Recorder 1
CEC version:   unknown
power status:  unknown
language:      ???


device #4: Playback 1
address:       2.1.0.0
active source: no
vendor:        Unknown
osd string:    Apple TV
CEC version:   unknown
power status:  on
language:      ???


device #5: Audio
address:       2.0.0.0
active source: no
vendor:        Samsung
osd string:    Soundbar
CEC version:   1.4
power status:  on
language:      ???


device #8: Playback 2
address:       2.2.0.0
active source: no
vendor:        Panasonic
osd string:    CECTester
CEC version:   1.4
power status:  on
language:      eng


currently active source: unknown (-1)
DEBUG:   [           55911]	expected response not received (82: active source)

sam_nazarko · 5 July 2019 12:45

So the Vero turns on the TV when you run cec-client still?

jaybird · 5 July 2019 13:05

Unfortunately yes.

Reboot Vero, putting devices on standby via TV remote = Everything stays asleep.

Wake devices up using TV remote, then put everything back to sleep again = Everything except the Apple TV powers back up.

Here’s an interesting snippet from the cec-client output just before the whole setup powers back up…

I believe Playback 1 = Apple TV, Playback 2 = Vero 4K+

I’m not sure if I’m interpreting it correctly, it looks like the second time the TV is powered off, Apple TV sends a CEC command to the chain of devices that wakes everything up?

TRAFFIC: [          143228] >> 4f:a6:06:10:56:10
DEBUG:   [          143229] >> Playback 1 (4) -> Broadcast (F): UNKNOWN (A6)
TRAFFIC: [          143451] >> 4f:85
DEBUG:   [          143451] >> 4 requests active source
DEBUG:   [          143451] Playback 1 (4): power status changed from 'standby' to 'on'
NOTICE:  [          143451] << Playback 2 (8) -> broadcast (F): active source (2200)
TRAFFIC: [          143451] << 8f:82:22:00
DEBUG:   [          143451] >> Playback 1 (4) -> Broadcast (F): request active source (85)

sam_nazarko · 5 July 2019 13:15

Ok, cool. Leave it with me.
I suspect if you set the Apple TV as active source, then turn off the TV, and run the command, it won’t turn back on.

jaybird · 5 July 2019 23:33

Many thanks again for the effort Sam!

The behaviour has always been like that - if it’s switched to the Apple TV as the active source, even without running the command, it was able to keep everything in standby when turning off the TV using the TV remote.

I’ve disabled libCEC on the Vero 4K+ in the mean time and await some good news

With libCEC disabled, it does seems like it’s no longer interfering with CEC/ARC functionality between the TV, sound bar and Apple TV. - Scratch that, CEC and ARC started to randomly become unavailable until Apple TV is powered back up.

Another noted behaviour from disabling libCEC on the Vero 4K+ is that switching sources on the sound bar (to the Apple TV or Vero 4K+) no longer results in the TV flickering and trying to switch resolution, which sometimes results in the Vero switching to random 720p/60 or 1080i/50 resolutions.

sam_nazarko · 6 July 2019 00:53

I should have some improvements for you to try tomorrow.

Sam

sam_nazarko · 7 July 2019 00:45

Sorry for the delay. I’ve made some changes.

Can you follow the instructions again as per: HDMI CEC struggles & wireless network performance on new Vero 4K+ - #25 by sam_nazarko

Sam

jaybird · 7 July 2019 12:15

Thanks Sam, unfortunately no dice, it’s still behaving in a similar manner - TV and receiver wakes up after being put into standby when active source is the Vero 4K+, stays asleep when active source is the ATV4K.

Tried re-setting libCEC config by defaulting it, turning off everything except specifying it being connected to AVR/Amplifier, port 2.

sam_nazarko · 7 July 2019 13:17

There is only one more patch that may resolve the issue, but it can break functionality with LG TVs.

It looks like this is an upstream bug in the Pulse Eight CEC library.

Can you post dpkg -l libcec-osmc so I can confirm you’ve updated successfully?

Sam

jaybird · 7 July 2019 13:34

Hi Sam, here’s the output:

osmc@osmc:~$ dpkg -l libcec-osmc

dpkg-query: no packages found matching libcec-osmc

From what I can recall, the last update done earlier in the day makes no mention to libcec packages being updated, re-doing it again shows one last component available:

osmc@osmc:~$ sudo apt-get update
Ign:3 http://ftp.debian.org/debian stretch InRelease                
Get:1 http://security-cdn.debian.org stretch/updates InRelease [94.3 kB]
Hit:4 http://ftp.debian.org/debian stretch-updates InRelease
Hit:5 http://ftp.debian.org/debian stretch Release 
Get:2 http://ftp.fau.de/osmc/osmc/apt stretch-devel InRelease [4,700 B]
Get:7 http://ftp.fau.de/osmc/osmc/apt stretch-devel/main armhf Packages.diff/Index [2,023 B]
Get:8 http://ftp.fau.de/osmc/osmc/apt stretch-devel/main armhf Packages [26.1 kB]
Fetched 127 kB in 5s (22.3 kB/s)   
Reading package lists... Done
osmc@osmc:~$ sudo apt-get dist-upgrade
Reading package lists... Done
Building dependency tree       
Reading state information... Done
Calculating upgrade... Done
The following packages will be upgraded:
  vero3-libcec-osmc
1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 303 kB of archives.
After this operation, 0 B of additional disk space will be used.
Do you want to continue? [Y/n]

I might try applying this and let you know of the results.

sam_nazarko · 7 July 2019 13:47

Sorry — should’ve been a grep there. It looks like you’re not on the latest version of CEC however

jaybird · 7 July 2019 14:03

Updated the package and we’re up from 4.0.4-3 to…

osmc@osmc:~$ dpkg -l | grep libcec-osmc
ii  vero3-libcec-osmc                    4.0.4-4                        armhf        libcec

Reset and reconfigured libCEC and it’s looking promising so far - Issue did recur once, and the Vero 4K+ did revert to 720p/60 randomly on several wake-ups.

I’ve disabled HDMI HPD to try, and will monitor it for the next day or two.

jaybird · 8 July 2019 08:17

So things are looking good with libCEC updated to 4.0.4-4, all the equipment are no longer waking up randomly by itself.

Disabling HDMI HPD also seem to have stopped Vero 4K+ from reverting to random resolutions.

There are only a few minor things that I’ve noticed:

Setting power saving to standby will result in the unit powering up (along with the sound bar and TV) at the preset interval, just for the Vero 4K+ box to go back into standby again, leaving the sound bar and TV active.
Not critical as I can live without automated standby - I’ve included some logs if you would like to peruse it - Standby timer is set to 5 minutes.
Was initially having issues with devices not staying asleep again when using the following keymap…

<keymap>
 <global>
  <keyboard>
   <key id="37">cecactivatesource</key>
  </keyboard>
 </global>
</keymap>

… but after a few restarts, things appears to have “settled down” and devices are behaving and no longer waking up randomly.

I’d say this is a solid fix @sam_nazarko !

It may also be worthwhile for @encdpnew try out this update to see if it resolves a similar issue he’s having?

sam_nazarko · 8 July 2019 13:18

Hm, that’s odd. I’ll check that out.