GPIOs 2&3 conflict with i2s_dacs detection (ControllerI2s)

[macmpi]

If one registers actions with GPIO 2 or 3, journalctl will show many errors like: i2c i2c-1: transfer timed out after restart. Indeed i2c-1 is on pins 3&5 (GPIOs 2&3) and is used by i2cDetect in here by ControllerI2s.prototype.onVolumioStart to detect i2s dacs when Volumio2 starts.

The issue is that gpio-buttons sets its triggers inGPIOButtons.prototype.onVolumioStart, so it may happen before ControllerI2s.prototype.onVolumioStart kicks-in since both are plugins... If gpio-buttons is first in sequence, GPIOs 2 or 3 are blocked by gpio-buttons triggers, and i2s detection fails with i2c i2c-1: transfer timed out (many of them!).

How can we ensure applyConf (which sets GPIOButtons triggers) happens after Volumio i2s detection is finished?

Thanks.

PS: I'm not using any DAC in this case, so all pins are free to use.

[thomaspasser]

Thanks for investigating this issue. I have been wondering if this could be a probem. Do you know what determines the plugin start order? As I have no clue how to solve this in a nice way, maybe pins 2 and 3 should be unusable in this plugin until a more sophisticated solution is found?

[volumio]

We have a priority system for plugin startup. Core plugins start before non-core, and there is a priority number from 1 to 10 (1 higher, 10 lower) in package.json of every plugin. So first move would be setting priority 10 in gpios. Second thing, the start script of gpiobuttons should be in onStart function, rather than onVolumio start.

[macmpi]

Thank you very much @volumio : making the 2 suggested changes fixed nearly all the error messages. I still have one poping-up, late in boot the process: will investigate more.

[macmpi]

@volumio here is the log with remaining i2c errors (I still happen to have many). It still seems gpio-buttons init (now with onStart, and priority 10) runs before ControllerI2s.prototype.onVolumioStart ends. This seems the only guy doing Nov 18 15:40:44 volumio sudo[1191]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cdetect -y 1 How can we make sure ControllerI2s finishes before gpio-buttons starts? Thanks.

PS: also, note volspotconnect (which as no boot priority set) starts after gpio-buttons which is set at priority 10

Nov 18 15:40:37 volumio volumio[938]: info: ___________ START PLUGINS ___________
Nov 18 15:40:37 volumio volumio[938]: PLUGIN START: appearance
Nov 18 15:40:37 volumio volumio[938]: PLUGIN START: last_100
Nov 18 15:40:37 volumio volumio[938]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Nov 18 15:40:37 volumio volumio[938]: info: [1479483637757] CoreMusicLibrary::Adding element Last_100
Nov 18 15:40:37 volumio volumio[938]: PLUGIN START: webradio
Nov 18 15:40:37 volumio volumio[938]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Nov 18 15:40:37 volumio volumio[938]: info: [1479483637853] CoreMusicLibrary::Adding element Webradio
Nov 18 15:40:37 volumio volumio[938]: PLUGIN START: my_volumio
==>Nov 18 15:40:38 volumio volumio[938]: PLUGIN START: gpio-buttons
Nov 18 15:40:38 volumio volumio[938]: info: GPIO-Buttons: Applying config file...
Nov 18 15:40:38 volumio volumio[938]: info: GPIO-Buttons: Shutdown on pin 3
==>Nov 18 15:40:38 volumio volumio[938]: info: GPIO-Buttons initialized
==>Nov 18 15:40:38 volumio volumio[938]: PLUGIN START: volspotconnect
Nov 18 15:40:38 volumio volumio[938]: info: Loading i18n strings for locale en
Nov 18 15:40:38 volumio wireless.js[992]: trying...
Nov 18 15:40:38 volumio sudo[1153]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volspotconnect.service
Nov 18 15:40:38 volumio sudo[1153]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 18 15:40:38 volumio volumio[938]: Updating browse sources language
Nov 18 15:40:38 volumio systemd[1]: Configuration file /etc/systemd/system/volspotconnect.service is marked executable. Please remove executable permission bits. Proceeding anyway.
Nov 18 15:40:38 volumio systemd[1]: Starting Volspotconnect Daemon...
Nov 18 15:40:38 volumio systemd[1]: Started Volspotconnect Daemon.
Nov 18 15:40:38 volumio sudo[1153]: pam_unix(sudo:session): session closed for user root
Nov 18 15:40:39 volumio volumio[938]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 18 15:40:39 volumio volumio[938]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 18 15:40:39 volumio volumio[938]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 18 15:40:39 volumio volumio[938]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 18 15:40:39 volumio volumio[938]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 18 15:40:39 volumio volumio[938]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 18 15:40:39 volumio volumio[938]: info: BOOT COMPLETED
Nov 18 15:40:39 volumio volumio[938]: Express server listening on port 3000
Nov 18 15:40:39 volumio wireless.js[992]: trying...
Nov 18 15:40:39 volumio volumio[938]: Volumio Calling Home
Nov 18 15:40:39 volumio volumio[1160]: Established under name 'volumio'
Nov 18 15:40:39 volumio volumio[938]: info: [1479483639950] CoreStateMachine::resetVolumioState
Nov 18 15:40:40 volumio volumio[938]: info: [1479483639996] CoreStateMachine::getcurrentVolume
Nov 18 15:40:40 volumio volumio[938]: info: CoreCommandRouter::volumioRetrievevolume
Nov 18 15:40:40 volumio volumio[938]: info: [1479483640258] CoreStateMachine::updateTrackBlock
Nov 18 15:40:40 volumio volumio[938]: info: [1479483640288] CorePlayQueue::getTrackBlock
Nov 18 15:40:40 volumio wireless.js[992]: trying...
Nov 18 15:40:41 volumio wireless.js[992]: trying...
Nov 18 15:40:42 volumio wireless.js[992]: trying...
Nov 18 15:40:43 volumio wireless.js[992]: trying...
Nov 18 15:40:44 volumio volumio[938]: info: Volspotconnect Daemon Started
Nov 18 15:40:44 volumio volumio[938]: info: MPD running with PID607 ,establishing connection
Nov 18 15:40:44 volumio wireless.js[992]: trying...
==>Nov 18 15:40:44 volumio sudo[1191]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cdetect -y 1
Nov 18 15:40:44 volumio sudo[1191]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 18 15:40:45 volumio volumio[938]: info: Setting Device type: Raspberry PI
Nov 18 15:40:45 volumio mpd[607]: client: [0] opened from ::ffff:127.0.0.1:47880
Nov 18 15:40:45 volumio wireless.js[992]: Overtime, starting plan B
Nov 18 15:40:45 volumio wireless.js[992]: killing: kill `pgrep -f "^/usr/bin/sudo"` || true
Nov 18 15:40:45 volumio wireless.js[992]: killing: kill `pgrep -f "^wpa_supplicant"` || true
==>Nov 18 15:40:45 volumio kernel: i2c i2c-1: transfer timed out
Nov 18 15:40:45 volumio sudo[1191]: pam_unix(sudo:session): session closed for user root
Nov 18 15:40:46 volumio kernel: R8188EU: ERROR indicate disassoc
Nov 18 15:40:48 volumio volumio[938]: info: [1479483648261] VolumeController:: Volume=100 Mute =false
Nov 18 15:40:48 volumio volumio[938]: info: [1479483648335] CoreStateMachine::pushState
Nov 18 15:40:48 volumio volumio[938]: info: [1479483648374] CoreStateMachine::getState
Nov 18 15:40:48 volumio volumio[938]: info: [1479483648382] CorePlayQueue::getTrack 0
Nov 18 15:40:48 volumio volumio[938]: info: CoreCommandRouter::volumioPushState
Nov 18 15:40:48 volumio volumio[938]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Nov 18 15:40:48 volumio volumio[938]: info: [1479483648507] InterfaceWebUI::pushState
Nov 18 15:40:48 volumio volumio[938]: info: Pushing Favourites {"service":"mpd","uri":"","favourite":false}
Nov 18 15:40:49 volumio systemd[1]: Stopped hotspot.service.
Nov 18 15:40:49 volumio wireless.js[992]: stophotspotchild process exited with code 0
Nov 18 15:40:49 volumio sudo[1211]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0
Nov 18 15:40:49 volumio sudo[1211]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 18 15:40:49 volumio sudo[1211]: pam_unix(sudo:session): session closed for user root
Nov 18 15:40:49 volumio sudo[1219]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down
Nov 18 15:40:49 volumio sudo[1219]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 18 15:40:49 volumio sudo[1219]: pam_unix(sudo:session): session closed for user root
Nov 18 15:40:49 volumio wireless.js[992]: Hotspot is disabled, not starting it
Nov 18 15:40:50 volumio wireless.js[992]: ifdeconfigchild process exited with code 0
Nov 18 15:40:50 volumio wireless.js[992]: ifconfig null
Nov 18 15:40:50 volumio wireless.js[992]: configwlanupchild process exited with code 0
Nov 18 15:40:50 volumio systemd[1]: Started Wireless Services.
==>Nov 18 15:40:51 volumio volumio[938]: info: Cannot read I2C interface or I2C interface not presentError: Command failed: /usr/bin/sudo /usr/sbin/i2cdetect -y 1
Nov 18 15:40:51 volumio volumio[938]: info: Volumio called home

[volumio]

First solution: try to remove the priority from the gpio-buttons plugin (but we will look into this as it seems a bug). Second solution: add a delay with settimeout to the initialization of gpio buttons plugin (on the onstart function)

what do you think?

[macmpi]

I'm a bit concerned with setting arbitrary delays for fixing non deterministic dependencies, as this may break later: can be a workaround at most; actually the current error messages are fine as they do not prevent GPIO3 action to work. Safer to keep the error until the root cause if debunked I guess.

With promises & defer chains, there should be a mean to know for sure when core Volumio startup & init sequences are finished for good I guess, right? Shouldn't we expect "add-on" plugins are started only after such point is reached?

[volumio]

That's what we should expect. But maybe something is not working as it should. In any case I agree with you: let's keep it this way instead of adding a delay. And let's fix the root cause...

[macmpi]

So, from your expectation, and looking at earlier log, at which point should ControllerI2s.prototype.onVolumioStart be finished then? Before info: ___________ START PLUGINS ___________?

Isn't it intriguing we see ControllerI2s.prototype.onVolumioStart issuing: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cdetect -y 1 well after START PLUGINS and even BOOT COMPLETED or Volumio Calling Home ?

[macmpi]

Been trying to trace what's happening inControllerI2s.prototype.onVolumioStart and particularly i2sDetect(). It seems that one starts and ends well before plugins kick-in, but, since it spawns a libQ method i2cDetect reading i2c1 through readI2S, that one gets out of sync...

This gets resolved too late in the game, even after START PLUGINS and even BOOT COMPLETED. In the meantime gpio_buttons plugin has started and registered an interrupt on i2c1 (GPIO3), so readI2S fails thereafter.

@volumio would it be acceptable to keep i2cDetect (and therefore readI2S) in sync, so that all is finished before plugins are started? Thanks.

[volumio]

That would mean refactoring those functions a lot... And using try catch to handle errors. It would not be a problem per se... However, I was thinking, why don't we just exclude such GPIOs from the plugin? They are used for i2c detection, for example with the pi touchscreen, so they would be problematic in any case. Is there a specific reason you want to keep them?

[macmpi]

...or, (since I understand i2cdetect -y 1 is taking ages and you may not want to delay startup to that much), instead of trying to detect "anything", can't we try to "bruteforce read" where/what would one expect from the list of DACs that are possible (since Volumio supports a list of known DACs)? If one of the reads works, then you know what device is plugged.

[macmpi]

GPIO3 is particularly interesting as it powers-up the pi. So using it for Shutdown action makes a lot of sense: one-button ON/OFF

EDIT: pi touchscreen does not seem to require use of GPIO3 (SCL)

[volumio]

We just read once, then we match what we read with possible results. I think this is the fastest way ...

[macmpi]

When there is no DAC, i2cdetect -y 1 just goes-on forever...

[volumio]

Mmm interesting. We can then give a timeout to this command {timeout: 1000}

What do you think?

[macmpi]

This seems to suggest it may take 1sec per transaction when nothing is connected to GPIO3 (SCL) due to clock stretching. This is indeed what I experience issuing i2cdetect -y 1 on command line: about 1'55" for the function to end !... How to test the timeout in your code?

[macmpi]

Timeout will certainly help so that i2cdetect -y 1 quits quicker when no devices use GPIO2-3 (no DAC using them, etc). But still, initial root cause is probably it starts after START PLUGINS and BOOT COMPLETED (even when gpio_buttons plugin is OFF). Can't we have that detection start (and end) sooner (or start plugins after it is completed...)?

[macmpi]

Closing it here and following-up on Volumio2 project page as it is definitely a Volumio issue in DAC auto-detection when i2S is set to OFF, no i2c devices connected. This does not prevent gpio-buttons from working on pin 2 & 3.