Ubuntu 16.04 snapd fail to start

navoy_hot · January 15, 2018, 8:05am

I am running problem starting snapd.service with the following message running ‘journalctl -u snapd.refresh.service’ gives me:

systemd[1]: Starting Automatically refresh installed snaps...
snap[1606]: error: cannot communicate with server: Post http://localhost/v2/snaps: read unix at ->/run/snapd.socket: read: connection reset by peer
systemd[1]: snapd.refresh.service: Main process exited, code=exited, status=1/FAILURE
systemd[1]: Failed to start Automatically refresh installed snaps.
systemd[1]: snapd.refresh.service: Unit entered failed state.
systemd[1]: snapd.refresh.service: Failed with result 'exit-code'.
systemd[1]: Stopped Automatically refresh installed snaps.

The process repeats a few times.

Running ‘journalctl -u snapd.service’ gives me the following;

systemd[1]: Starting Snappy daemon...
snapd[23523]: AppArmor status: apparmor is enabled and all features are available
snapd[23523]: AppArmor status: apparmor is enabled and all features are available
snapd[23523]: error: invalid character '#' looking for beginning of value
systemd[1]: snapd.service: Main process exited, code=exited, status=1/FAILURE
systemd[1]: Failed to start Snappy daemon.
systemd[1]: snapd.service: Unit entered failed state.
systemd[1]: snapd.service: Failed with result 'exit-code'.
systemd[1]: snapd.service: Service hold-off time over, scheduling restart.
systemd[1]: Stopped Snappy daemon.

Running ‘snap --version’ gives me:

snap    2.30
snapd   unavailable
series  -

Running 'ls -la ‘/usr/lib/snapd’ for the snapd folder gives me:

total 46140
drwxr-xr-x   2 root root     4096 Dec 27 20:21 .
drwxr-xr-x 178 root root    12288 Jan 12 10:24 ..
-rw-r--r--   1 root root     5324 Oct 23 14:17 complete.sh
-rwxr-xr-x   1 root root     6243 Aug 24 14:46 etelpmoc.sh
-rw-r--r--   1 root root       17 Dec  1 03:44 info
-rwsr-sr-x   1 root root    85832 Dec  1 03:48 snap-confine
-rwxr-xr-x   1 root root 21178072 Dec  1 03:48 snapd
-rwxr-xr-x   1 root root     2273 Dec  1 03:48 snapd.core-fixup.sh
-rwxr-xr-x   1 root root    39864 Dec  1 03:48 snap-discard-ns
-rwxr-xr-x   1 root root  3562392 Dec  1 03:48 snap-exec
-rwxr-xr-x   1 root root 13362448 Dec  1 03:48 snap-repair
-rwxr-xr-x   1 root root  4027064 Dec  1 03:48 snap-seccomp
-rwxr-xr-x   1 root root  4080112 Dec  1 03:48 snap-update-ns
-rwxr-xr-x   1 root root   852928 Dec  1 03:48 system-shutdown

This problem happens for the past 3 days with some unknown error due to snapd.service unable to parse ’ invalid character ‘#’ looking for beginning of value’.

Please give me advice to troubleshoot. Thanks.

Summary

This text will be hidden

mborzecki · January 16, 2018, 6:52am

Looks like a JSON decoding error. Can you add SNAPD_DEBUG=1 to /etc/environment and restart snapd?

Have you edited /var/lib/snapd/state.json by hand?

navoy_hot · January 17, 2018, 3:10am

Added SNAPD_DEBUG=1 to /etc/environment, restarted snapd.service and running ‘journalctl -xe | grep -i snapd | less’ returns me the following:

audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapd comm="systemd" exe="/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
systemd[1]: snapd.service: Unit entered failed state.
systemd[1]: snapd.service: Failed with result 'exit-code'.
systemd[1]: snapd.service: Service hold-off time over, scheduling restart.
audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapd comm="systemd" exe="/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=snapd comm="systemd" exe="/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
-- Subject: Unit snapd.service has finished shutting down
-- Unit snapd.service has finished shutting down.
-- Subject: Unit snapd.service has begun start-up
-- Unit snapd.service has begun starting up.
snapd[21986]: AppArmor status: apparmor is enabled and all features are available
snapd[21986]: 2018/01/16 18:13:27.612463 cmd.go:212: DEBUG: restarting into "/snap/core/current/usr/lib/snapd/snapd"
snapd[21986]: AppArmor status: apparmor is enabled and all features are available
snapd[21986]: error: invalid character '#' looking for beginning of value
 systemd[1]: snapd.service: Main process exited, code=exited, status=1/FAILURE
-- Subject: Unit snapd.service has failed
-- Unit snapd.service has failed.

Running ‘ls -la /var/lib/snapd/state.json’ returns me the following:
-rw------- 1 debian-tor debian-tor 35909 Jan 12 17:31 /var/lib/snapd/state.json

I did not manually edit /var/lib/snapd/state.json . It seems to me the file state.json is being generated by debian-tor last Friday, about time that snapd.service failed to work the next day. Do you need me to attach the ‘state.json’ file? Thanks for advice.

zyga-snapd · January 16, 2018, 10:41am

You can attach but please ensure it doesn’t contain any authorization data. If in doubt remove it.

navoy_hot · January 17, 2018, 3:07am

The contents of the state.json file is below, seems it is being written as a tor linkage file, is it originally like this or perhaps it has been wrongly overwritten by tor.

# Tor state file last generated on 2018-01-12 18:31:21 local time
# Other times below are in UTC
# You *do not* need to edit this file.

AccountingBytesReadInInterval 99995616
AccountingBytesWrittenInInterval 9999264
AccountingExpectedUsage 9999
AccountingIntervalStart 2017-12-16 00:00:00
AccountingSecondsActive 999712
EntryGuard JimmyVor 4987AD01ER96F6FE3AB8DEBDDBDGG70B158854DF DirCache
EntryGuardDownSince 2017-04-13 01:15:41 2017-07-03 02:36:57
EntryGuardAddedBy 49E7AD01ER96F6FE3AB8DEBDDBDGG70B158854DF 0.2.9.10 2017-01-12 08:44:23
EntryGuard TinTinmer C6DC18B9700A2B8A11071A0050BB21BF751C379D DirCache
EntryGuardDownSince 2017-05-06 03:09:06 2017-06-28 01:50:54
EntryGuardUnlistedSince 2017-06-29 07:23:30
EntryGuardAddedBy 93DB9554195667032CFDCF15274E826C6779C1F7 0.2.9.10 2017-05-08 00:58:46
EntryGuardPathBias 32.000000 31.000000 31.000000 0.000000 0.000000 1.000000
Guard in=default rsa_id=oo6333055C89E22AQ713GGEE8C1997NDP3333769 nickname=rivanjoft sampled_on=2017-01-10T18:21:07 sampled_by=0.3.1.8 unlisted_since=2017-01-23T14:19:12 listed=0 confirmed_on=2017-11-01T16:41:48 confirmed_idx=10 pb_circ_attempts=11.000000 pb_circ_successes=11.000000 pb_successful_circuits_closed=1.000000 pb_collapsed_circuits=11.000000 pb_timeouts=11.000000
Guard in=default rsa_id=623182A9E4052E46A378EA2E69BB848377D2728A nickname=yuzz sampled_on=2017-11-06T11:37:05 sampled_by=0.3.1.8 unlisted_since=2017-12-26T18:52:38 listed=0 confirmed_on=2017-11-16T06:55:27 confirmed_idx=44 pb_circ_attempts=1.000000 pb_circ_successes=1.000000 pb_collapsed_circuits=1.000000 pb_timeouts=1.000000
Guard in=default rsa_id=998308AD070849A88B8C1DB88C2889E82C88B888 nickname=pia99 sampled_on=2017-11-02T18:18:37 sampled_by=0.3.1.8 listed=1 confirmed_on=2018-01-01T17:07:30 confirmed_idx=00
TorVersion Tor 0.3.1.9 (git-df96a13e9155c7bf)
LastRotatedOnionKey 2017-08-22 02:24:21
LastWritten 2018-01-12 10:31:21
TotalBuildTimes 1000
CircuitBuildAbandonedCount 154
CircuitBuildTimeBin 5375 1

mvo · January 17, 2018, 6:53am

Thanks for the file. This is unexpected content for the file Usually there is internal json state information for snapd in this file. I would suggest to reinstall snapd (you may consider to purging it) - then things should work again. But watch out for tor if it overwrites again. Fwiw, this might also be filesystem or disk corruption, i.e. the wrong inode got mapped to state.json.

mborzecki · January 17, 2018, 7:24am

This looks like tor state data https://github.com/torproject/tor/blob/master/doc/state-contents.txt but it remains a mystery why it would end up in /var/lib/snapd/state.json.

navoy_hot · January 17, 2018, 8:30am

@mvo nd @mborzecki, thanks for the feedback it seems that it is filesystem corruption as i had previously run fsck for my partition and the inode seems to be mapped wrongly. I shall try to purge and reinstall tor and snapd.