HA restart on HAOS with USB modem hangs for about 10 minutes (happens every few restarts)

[blackie333]

Describe the issue you are experiencing

Hello, after upgrade to HAOS 9 the following problem started to appear during restart of HA Core:
HA hangs during the startup for about 10 minutes and blocks the whole startup from finishing.
Logger: homeassistant.bootstrap
Source: bootstrap.py:441
First occurred: 7:53:58 AM (7 occurrences)
Last logged: 8:00:00 AM
Waiting on integrations to complete setup: sms

Have tried several times to restart HA or reboot the whole HAOS but the problem persists.
The problem is repeating every few HA restarts and always hangs at SMS integration starting.
If it happens startup hangs with "Starting SMS notifications via GSM-modem, not everything..." for about 10 minutes until the message finally goes away and startup sequence finishes.

Today the 4th HA restart got stuck again for 10 minutes, other 3 restarts finished until 90 seconds as usual.

I use OdroidC4 HAOS installation with the lastest versions of all components.
Discussed the issue in SMS integration thread and the author suggested to create a new issue for HAOS.
Thanks for looking into this.

What operating system image do you use?

odroid-c4 (Hardkernel ODROID-C4)

What version of Home Assistant Operating System is installed?

9.2

Did you upgrade the Operating System.

Yes

Steps to reproduce the issue

1. USB modem installed with related integration "SMS notifications via GSM-modem"
2. Restart HA core a few times (for example after changing configuration.yaml but not related)
3. Some of the restarts will hang at message "Starting SMS notifications via GSM-modem, ..." for about 10 minutes
   ...

Anything in the Supervisor logs that might be useful for us?

22-10-26 17:45:46 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
22-10-26 17:45:46 INFO (MainThread) [supervisor.homeassistant.core] Detect a running Home Assistant instance
22-10-26 17:47:05 INFO (SyncWorker_1) [supervisor.docker.interface] Restarting ghcr.io/home-assistant/odroid-c4-homeassistant
22-10-26 17:47:26 INFO (MainThread) [supervisor.homeassistant.core] Wait until Home Assistant is ready
22-10-26 17:47:37 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state CoreState.RUNNING
22-10-26 17:47:37 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
22-10-26 17:47:38 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/esphome/home-assistant-addon repository
22-10-26 17:47:38 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/zigbee2mqtt/hassio-zigbee2mqtt/ repository
22-10-26 17:47:39 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/home-assistant/addons repository
22-10-26 17:47:39 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/hassio-addons/repository repository
22-10-26 17:47:39 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
22-10-26 17:47:42 INFO (MainThread) [supervisor.store] Loading add-ons from store: 71 all - 0 new - 0 remove
22-10-26 17:47:42 INFO (MainThread) [supervisor.store] Loading add-ons from store: 71 all - 0 new - 0 remove

Anything in the Host logs that might be useful for us?

[353349.932735] audit: type=1327 audit(1666799088.247:1230): proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F7661722F72756E2F646F636B65722F636F6E7461696E6572642F6461656D6F6E2F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F62613833343865
[353349.932914] audit: type=1334 audit(1666799088.251:1231): prog-id=468 op=LOAD
[353349.932945] audit: type=1300 audit(1666799088.251:1231): arch=c00000b7 syscall=280 success=yes exit=17 a0=5 a1=40001959b0 a2=78 a3=0 items=0 ppid=515603 pid=515613 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
[353349.932958] audit: type=1327 audit(1666799088.251:1231): proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F7661722F72756E2F646F636B65722F636F6E7461696E6572642F6461656D6F6E2F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F62613833343865
[353349.932972] audit: type=1334 audit(1666799088.251:1232): prog-id=0 op=UNLOAD
[353349.933070] audit: type=1334 audit(1666799088.251:1233): prog-id=0 op=UNLOAD
[353349.933213] audit: type=1334 audit(1666799088.251:1234): prog-id=469 op=LOAD
[353385.580618] systemd-journald[159]: Data hash table of /var/log/journal/6be53845713f48f49fa6c725f145b847/system.journal has a fill level at 75.0 (174764 of 233016 items, 134217728 file size, 767 bytes per hash table item), suggesting rotation.
[353385.580646] systemd-journald[159]: /var/log/journal/6be53845713f48f49fa6c725f145b847/system.journal: Journal header limits reached or header out-of-date, rotating.
[353399.073640] Bluetooth: hci0: No such LE device xx:xx:xx:xx:xx:xx (0x0)
[353507.343087] kauditd_printk_skb: 2 callbacks suppressed
[353507.343098] audit: type=1334 audit(1666799245.669:1235): prog-id=0 op=UNLOAD
[353507.639781] audit: type=1334 audit(1666799245.965:1236): prog-id=470 op=LOAD
[353507.639805] audit: type=1300 audit(1666799245.965:1236): arch=c00000b7 syscall=280 success=yes exit=15 a0=5 a1=4000145c40 a2=78 a3=0 items=0 ppid=516243 pid=516253 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
[353507.639819] audit: type=1327 audit(1666799245.965:1236): proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F7661722F72756E2F646F636B65722F636F6E7461696E6572642F6461656D6F6E2F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F62613833343865
[353507.640002] audit: type=1334 audit(1666799245.965:1237): prog-id=471 op=LOAD
[353507.640065] audit: type=1300 audit(1666799245.965:1237): arch=c00000b7 syscall=280 success=yes exit=17 a0=5 a1=40001459b0 a2=78 a3=0 items=0 ppid=516243 pid=516253 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
[353507.640078] audit: type=1327 audit(1666799245.965:1237): proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F7661722F72756E2F646F636B65722F636F6E7461696E6572642F6461656D6F6E2F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F62613833343865
[353507.640094] audit: type=1334 audit(1666799245.965:1238): prog-id=0 op=UNLOAD
[353507.640176] audit: type=1334 audit(1666799245.965:1239): prog-id=0 op=UNLOAD
[353507.640348] audit: type=1334 audit(1666799245.965:1240): prog-id=472 op=LOAD

System information

Home Assistant 2022.10.5
Supervisor 2022.10.0
Operating System 9.2
Frontend 20221010.0 - latest

Additional information

My modem has a weak signal and reports it in the HA log:
Logger: homeassistant.components.sms
Source: helpers/update_coordinator.py:151
Integration: SMS notifications via GSM-modem (documentation, issues)
First occurred: 6:00:23 PM (4 occurrences)
Last logged: 6:12:13 PM

Timeout fetching Device signal state data
Timeout fetching Device network state data

Logger: homeassistant
Source: /usr/src/homeassistant/homeassistant/runner.py:96
First occurred: 6:11:32 PM (34 occurrences)
Last logged: 6:11:33 PM

Error doing job: Exception in callback Future.set_result({'BitErrorRate': -1, 'SignalPercent': 72, 'SignalStrength': -65})
Error doing job: Exception in callback Future.set_result({'CID': '0055EB35', 'GPRS': 'Attached', 'LAC': '0BCA', 'NetworkCode': '231 01', ...})
Error doing job: Exception in callback Future.set_result({'BitErrorRate': -1, 'SignalPercent': 63, 'SignalStrength': -71})
Error doing job: Exception in callback Future.set_result({'BitErrorRate': -1, 'SignalPercent': 69, 'SignalStrength': -67})
Traceback (most recent call last):
File "/usr/local/lib/python3.10/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
asyncio.exceptions.InvalidStateError: invalid state

[agners]

Best approach to make sure this is an OS related issue is to downgrade to the known latest HAOS version and see if that indeed fixes the problem. HAOS downgrades are fairly safe. Use the following command in the terminal, e.g. to downgrade to HAOS 8.5:

ha os update --version 8.5

[agners]

Maybe its worth trying 9.3 first, as it comes with a kernel update as well.

[blackie333]

Upgrade to new HAOS 9.3 didn't helped, the issue persists.
Will try to downgrade HAOS to 8.5 later, need to backup my production system first.

[github-actions]

There hasn't been any activity on this issue recently. To keep our backlog manageable we have to clean old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant OS version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[blackie333]

The issue seems to be fixed with the recent updates to HAOS and modem integration. Thanks

[github-actions]

There hasn't been any activity on this issue recently. To keep our backlog manageable we have to clean old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant OS version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.