Device gets bricked after trying to upgrade Core snap

denis · May 1, 2017, 2:54pm

I have a custom armhf board with custom gadget and kernel snap. All that assembled with ubuntu-image.

denisnone@localhost:~$ uname -a
Linux localhost.localdomain 4.10.1-dac_cpu+ #1 SMP Tue Apr 25 11:27:22 CEST 2017 armv7l armv7l armv7l GNU/Linux

This is the initial point before refresh:

denisnone@localhost:~$ snap info core
name:      core
summary:   "snapd runtime environment"
publisher: canonical
contact:   snappy-canonical-storeaccount@canonical.com
description: |
  The core runtime environment for snapd
type:        core
tracking:    candidate
installed:   16-2 (1690) 70MB -
refreshed:   2017-04-11 12:29:57 +0000 UTC
channels:                
  stable:    16-2 (1580) 69MB -
  candidate: 16-2 (1690) 70MB -
  beta:      16-2 (1805) 71MB -
  edge:      16-2 (1823) 70MB -

Running this:

denisnone@localhost:~$ snap refresh core --beta

Then it freezes on this stage:

[|] Setup snap "core" (1805) security profiles (phase 2)

The slash keeps spinning until finally scheduled reboot comes.

It reboots well but:

denisnone@localhost:~$ snap change 38
Status  Spawn                 Ready                 Summary
Undone  2017-05-01T13:39:06Z  2017-05-01T13:52:02Z  Download snap "core" (1805) from channel "beta"
Done    2017-05-01T13:39:06Z  2017-05-01T13:51:59Z  Fetch and check assertions for snap "core" (1805)
Undone  2017-05-01T13:39:06Z  2017-05-01T13:52:07Z  Mount snap "core" (1805)
Undone  2017-05-01T13:39:06Z  2017-05-01T13:52:05Z  Stop snap "core" services
Undone  2017-05-01T13:39:06Z  2017-05-01T13:52:05Z  Remove aliases for snap "core"
Undone  2017-05-01T13:39:06Z  2017-05-01T13:52:04Z  Make current revision for snap "core" unavailable
Undone  2017-05-01T13:39:06Z  2017-05-01T13:52:04Z  Copy snap "core" data
Undone  2017-05-01T13:39:06Z  2017-05-01T13:52:04Z  Setup snap "core" (1805) security profiles
Undone  2017-05-01T13:39:06Z  2017-05-01T13:52:00Z  Make snap "core" (1805) available to the system
Error   2017-05-01T13:39:06Z  2017-05-01T13:51:59Z  Setup snap "core" (1805) security profiles (phase 2)
Hold    2017-05-01T13:39:06Z  2017-05-01T13:51:59Z  Set automatic aliases for snap "core"
Hold    2017-05-01T13:39:06Z  2017-05-01T13:51:59Z  Setup snap "core" aliases
Hold    2017-05-01T13:39:06Z  2017-05-01T13:51:59Z  Start snap "core" (1805) services
Hold    2017-05-01T13:39:06Z  2017-05-01T13:51:59Z  Clean up "core" (1805) install
Hold    2017-05-01T13:39:06Z  2017-05-01T13:51:59Z  Run configure hook of "core" snap if present

......................................................................
Setup snap "core" (1805) security profiles

2017-05-01T13:52:00Z INFO cannot auto connect core:core-support-plug to core:core-support: (plug auto-connection), existing connection state "core:core-support-plug core:core-support" in the way
2017-05-01T13:52:00Z INFO cannot auto connect alsa-utils:alsa to core:alsa: (slot auto-connection), existing connection state "alsa-utils:alsa core:alsa" in the way
2017-05-01T13:52:00Z INFO cannot auto connect core:core-support-plug to core:core-support: (slot auto-connection), existing connection state "core:core-support-plug core:core-support" in the way
2017-05-01T13:52:00Z INFO cannot auto connect avahi:network to core:network: (slot auto-connection), existing connection state "avahi:network core:network" in the way
2017-05-01T13:52:00Z INFO cannot auto connect avahi:network-bind to core:network-bind: (slot auto-connection), existing connection state "avahi:network-bind core:network-bind" in the way
2017-05-01T13:52:00Z INFO cannot auto connect avahi:network-control to core:network-control: (slot auto-connection), existing connection state "avahi:network-control core:network-control" in the way
2017-05-01T13:52:00Z INFO cannot auto connect network-manager:network-setup-observe to core:network-setup-observe: (slot auto-connection), existing connection state "network-manager:network-setup-observe core:network-setup-observe" in the way
2017-05-01T13:52:00Z INFO cannot auto connect network-manager:ppp to core:ppp: (slot auto-connection), existing connection state "network-manager:ppp core:ppp" in the way

......................................................................
Make snap "core" (1805) available to the system

2017-05-01T13:40:24Z INFO Requested system restart.

......................................................................
Setup snap "core" (1805) security profiles (phase 2)

2017-05-01T13:40:24Z INFO Waiting for restart...
2017-05-01T13:43:41Z INFO Waiting for restart...
2017-05-01T13:48:41Z INFO Waiting for restart...
2017-05-01T13:51:59Z ERROR cannot finish core installation, there was a rollback across reboot[/details]

Then I issue a second reboot after refresh. But it finishes in initramfs.

[    3.064006] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    3.097047] EXT4-fs (mmcblk0p3): couldn't mount as ext3 due to feature incompatibilities
[    3.120599] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null)
mount: mounting /tmpmnt_writable/system-data/var/lib/snapd/snaps/core_1805.snap on /root failed: No such file or directory
[    3.200996] UDF-fs: warning (device loop0): udf_fill_super: No partition found (2)
mount: mounting /tmpmnt_kernel/modules on /root/lib/modules failed: No such file or directory
mount: mounting /tmpmnt_kernel/firmware on /root/lib/firmware failed: No such file or directory
[    3.242151] initrd: mounting /run
mount: mounting tmpfs on /root/run failed: No such file or directory
mount: mounting /tmpmnt_writable on /root/writable failed: No such file or directory
/init: line 9: can't create /root/etc/fstab: nonexistent directory
mount: mounting /root/writable/system-data/etc/systemd/system on /root/etc/systemd/system failed: No such file or directory
mount: mounting /root/writable/system-data/etc/machine-id on /root/etc/machine-id failed: No such file or directory
Begin: Running /scripts/local-bottom ... done.
done.
Begin: Running /scripts/nfs-bottom ... done.
Begin: Running /scripts/init-bottom ... mount: mounting /dev on /root/dev failed: No such file or directory
done.
mount: mounting /run on /root/run failed: No such file or directory
run-init: current directory on the same filesystem as the root: error 0
Target filesystem doesn't have requested /lib/systemd/systemd.
run-init: current directory on the same filesystem as the root: error 0
run-init: current directory on the same filesystem as the root: error 0
run-init: current directory on the same filesystem as the root: error 0
run-init: current directory on the same filesystem as the root: error 0
run-init: current directory on the same filesystem as the root: error 0
No init found. Try passing init= bootarg.


BusyBox v1.22.1 (Ubuntu 1:1.22.0-15ubuntu1) built-in shell (ash)
Enter 'help' for a list of built-in commands.

(initramfs)

What we see in snap directory: Only an old core snap:

(initramfs) cd /tmpmnt_writable/system-data/var/lib/snapd/snaps/
(initramfs) ls -al
drwxr-xr-x   11      4096 ..
-rw-r--r--    2    708608 dac-cpu_x1.snap
-rw-r--r--    2   4624384 network-manager_167.snap
drwxr-xr-x    2      4096 .
-rw-r--r--    2   1097728 avahi_36.snap
-rw-r--r--    2   6074368 alsa-utils_69.snap
-rw-r--r--    1  70746112 core_1690.snap
-rw-r--r--    2  67387392 maincontroller_x1.snap
-rw-r--r--    2    221184 htop_71.snap
-rw-r--r--    1      4096 classic_17.snap
-rw-r--r--    1  26292224 dac-cpu-kernel_x1.snap
(initramfs)

Trying to hack it:

(initramfs) mv core_1690.snap core_1805.snap
(initramfs) reboot

And yes it boots, but complains about it:

denisnone@localhost:~$ snap info core
name:      core
summary:   ""
publisher: canonical
contact:   snappy-canonical-storeaccount@canonical.com
description: |
  
tracking:    candidate
installed:     (1690) 0B broken
refreshed:   2017-04-25 09:49:16.783809299 +0000 UTC
channels:                
  stable:    16-2 (1580) 69MB -
  candidate: 16-2 (1690) 70MB -
  beta:      16-2 (1805) 71MB -
  edge:      16-2 (1823) 70MB - [/details]

So basically what it does is harakiri. It can’t cure itself without intervention.

And interesting fact: I couldn’t get core snap refreshed not even once. And not only force refresh leads to death, but also when a new version of core comes out in a particular tracking channel. (No surprise) What can cause the problem? Kernel? Gadget? ubuntu-image?

I have a raspi3 and it switches cores and channels smoothly on it’s official image. It still hangs on “Setup snap “core” () security profiles (phase 2)”. But after reboot it’s on a new core snap.

The kernel is a zesty kernel from official Ubuntu repository from master branch. It couldn’t get xenial kernel working on my board, besides I need some improvements incorporated in linux 4.6-4.8, so 4.4 is not an option for me.

zyga-snapd · May 1, 2017, 3:44pm

Hey

Can you please share any relevant journal/syslog messages? Before trying to refresh the core snap, did you try to refresh / install anything else (e.g. even hello-world) if so, did that succeed?

Can you tell me more about this. Is this using stock PI3 kernel/gadget image? If so I’ll try to reproduce this.

zyga-snapd · May 1, 2017, 3:51pm

Ah, I missed this. Those expanders are unfamiliar to me. So, this is very interesting. Can you please harvest system log messages that are related to this this time?

mvo · May 1, 2017, 4:27pm

Thanks for this report and sorry for the trouble you experience. Could you please paste the output of:

$ fw_printenv |grep snap

I.e. the boot configuration of uboot would be great.

There are at least two bugs here:

fails to connect the interfaces (core-support)
fails to rollback from the broken core

The uboot environment hopefully helps with figuring out why (2). The syslog data that @zyga-snapd asked for should help with (1).

Thanks!

kyrofa · May 1, 2017, 4:31pm

Judging from the first sentence of the original post, I’d say no .

denis · May 1, 2017, 4:36pm

Hello,

On raspberry-pi3 this works silently in the background when a new core version comes out.
But when forced to refresh from a terminal via ssh this gives that:
Before refresh:

denisnone@rpic:~$ snap info core
name:      core
summary:   "snapd runtime environment"
publisher: canonical
contact:   snappy-canonical-storeaccount@canonical.com
description: |
  The core runtime environment for snapd
type:        core
tracking:    edge
installed:   16-2 (1637) 70MB -
refreshed:   2017-04-06 04:23:48 +0000 UTC
channels:                
  stable:    16-2 (1580) 69MB -
  candidate: 16-2 (1690) 70MB -
  beta:      16-2 (1805) 71MB -
  edge:      16-2 (1823) 70MB -

Refresh process:

denisnone@rpic:~$ snap refresh core --candidate
[/] Download snap "core" (1690) from channel "candidate"
Broadcast message from root@rpic (Mon 2017-05-01 16:10:00 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:20:00 UTC!

core 45.84 MB / 67.47 MB [=====================================================================>---------------------------------]  67.95% 792.48 KB/s 27s
Broadcast message from root@rpic (Mon 2017-05-01 16:11:00 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:20:00 UTC!

[\] Mount snap "core" (1690)
Broadcast message from root@rpic (Mon 2017-05-01 16:12:00 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:20:00 UTC!

[/] Make snap "core" (1690) available to the system
Broadcast message from root@rpic (Mon 2017-05-01 16:12:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

2017-05-01T16:12:06Z INFO Waiting for restart...
[-] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:13:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

[\] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:14:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

[|] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:15:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

[/] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:16:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

2017-05-01T16:16:45Z INFO Waiting for restart...
[-] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:17:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

[\] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:18:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

[|] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:19:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

[/] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:20:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

[-] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:21:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 16:22:06 UTC!

2017-05-01T16:21:45Z INFO Waiting for restart...
[\] Setup snap "core" (1690) security profiles (phase 2)
Broadcast message from root@rpic (Mon 2017-05-01 16:22:06 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot NOW!

Connection to rpic.local closed by remote host.
Connection to rpic.local closed.

After reboot

denisnone@rpic:~$ snap info core
name:      core
summary:   "snapd runtime environment"
publisher: canonical
contact:   snappy-canonical-storeaccount@canonical.com
description: |
  The core runtime environment for snapd
type:        core
tracking:    candidate
installed:   16-2 (1690) 70MB -
refreshed:   2017-04-11 12:29:57 +0000 UTC
channels:                
  stable:    16-2 (1580) 69MB -
  candidate: 16-2 (1690) 70MB -
  beta:      16-2 (1805) 71MB -
  edge:      16-2 (1823) 70MB -
denisnone@rpic:~$

Changes info:

denisnone@rpic:~$ snap changes
ID   Status  Spawn                 Ready                 Summary
19   Done    2017-05-01T16:09:54Z  2017-03-14T20:19:03Z  Refresh "core" snap from "candidate" channel
20   Done    2017-05-01T16:09:56Z  2017-05-01T16:10:26Z  

denisnone@rpic:~$ snap change 19
Status  Spawn                 Ready                 Summary
Done    2017-05-01T16:09:54Z  2017-05-01T16:11:26Z  Download snap "core" (1690) from channel "candidate"
Done    2017-05-01T16:09:54Z  2017-05-01T16:12:00Z  Fetch and check assertions for snap "core" (1690)
Done    2017-05-01T16:09:54Z  2017-05-01T16:12:03Z  Mount snap "core" (1690)
Done    2017-05-01T16:09:54Z  2017-05-01T16:12:03Z  Stop snap "core" services
Done    2017-05-01T16:09:54Z  2017-05-01T16:12:03Z  Remove aliases for snap "core"
Done    2017-05-01T16:09:54Z  2017-05-01T16:12:04Z  Make current revision for snap "core" unavailable
Done    2017-05-01T16:09:54Z  2017-05-01T16:12:04Z  Copy snap "core" data
Done    2017-05-01T16:09:54Z  2017-05-01T16:12:05Z  Setup snap "core" (1690) security profiles
Done    2017-05-01T16:09:54Z  2017-05-01T16:12:06Z  Make snap "core" (1690) available to the system
Done    2017-05-01T16:09:54Z  2017-03-14T20:18:55Z  Setup snap "core" (1690) security profiles (phase 2)
Done    2017-05-01T16:09:54Z  2017-03-14T20:18:55Z  Set automatic aliases for snap "core"
Done    2017-05-01T16:09:54Z  2017-03-14T20:18:55Z  Setup snap "core" aliases
Done    2017-05-01T16:09:54Z  2017-03-14T20:18:55Z  Start snap "core" (1690) services
Done    2017-05-01T16:09:54Z  2017-03-14T20:18:56Z  Remove data for snap "core" (1580)
Done    2017-05-01T16:09:54Z  2017-03-14T20:18:59Z  Remove snap "core" (1580) from the system
Done    2017-05-01T16:09:54Z  2017-03-14T20:18:59Z  Clean up "core" (1690) install
Done    2017-05-01T16:09:54Z  2017-03-14T20:19:03Z  Run configure hook of "core" snap if present

......................................................................
Make snap "core" (1690) available to the system

2017-05-01T16:12:06Z INFO Requested system restart.

......................................................................
Setup snap "core" (1690) security profiles (phase 2)

2017-05-01T16:12:06Z INFO Waiting for restart...
2017-05-01T16:16:45Z INFO Waiting for restart...
2017-05-01T16:21:45Z INFO Waiting for restart...

denisnone@rpic:~$

So it refreshes well, but it sits in that “security profiles (phase 2)” forever until scheduled reboot hits.
And yes, the image is an Ubuntu official image.

About my board.
Installing/removing snaps works without problems, “hello-world” for example installs well.

Docker snap installs but gives an INFO:

2017-05-01T16:32:11Z INFO cannot auto connect docker:docker-cli to docker:docker-daemon: (slot auto-connection), existing connection state "docker:docker-cli docker:docker-daemon" in the way
docker 1.13.1-0 from 'docker-inca' installed

I will collect journald information and post it shortly after re-flashing my image on sd-card to clean all the mess and start over again.

denis · May 1, 2017, 4:38pm

I have two boards: my custom board with my custom image and a reference one - raspi3 with official image.

ogra · May 1, 2017, 5:13pm

dropping into the initramfs prompt indicates either an issue with your kernel snap (wrong or broken initrd) or (more likely since it originally booted) an issue with the updating of the bootloader variables in uboot after core upgrade.

do you get a proper listing of gadget, kernel and core snap after a fresh flash of your custom image when using “snap list” right after first login (i.e. was your image initialized properly on first boot) ?
can you show us your uboot environment … (as @mvo said above, the output of fw_printenv is essential here)
does your uboot have the proper patches and did you create a 131072 bytes big redundant uboot.env file when creating the gadget (see README.md of the pi3 gadget on how to create it) ?

denis · May 1, 2017, 6:56pm

Hello, @ogra, @mvo.

After first boot this looks like that:

denisnone@localhost:~$ snap list
Name            Version  Rev   Developer  Notes
alsa-utils      1.1.2-5  69    canonical  -
avahi           0.6.32   36    ondra      -
core            16-2     1580  canonical  -
dac-cpu         16.04-1  x1               -
dac-cpu-kernel  4.7.0    x1               -
htop            2.0.2    71    maxiberta  -

Gadget and kernel snap are listed well.
Initialize device seems to fail:

denisnone@localhost:~$ snap changes
ID   Status  Spawn                 Ready                 Summary
1    Done    2017-05-01T17:06:21Z  2017-05-01T17:09:36Z  Initialize system state
2    Error   2017-05-01T17:06:38Z  2017-05-01T17:26:16Z  Initialize device
3    Error   2017-05-01T17:26:16Z  2017-05-01T17:31:01Z  Initialize device
4    Do      2017-05-01T17:40:59Z  -                     Initialize device

denisnone@localhost:~$ snap change 3
Status  Spawn                 Ready                 Summary
Done    2017-05-01T17:26:16Z  2017-05-01T17:31:01Z  Run prepare-device hook
Done    2017-05-01T17:26:16Z  2017-05-01T17:31:01Z  Generate device key
Error   2017-05-01T17:26:16Z  2017-05-01T17:31:01Z  Request device serial

......................................................................
Request device serial

2017-05-01T17:31:01Z ERROR cannot deliver device serial request: Cannot process serial request for device with brand "u****wrSD", store can sign serial only for brand "canonical"

Considering uboot:

denisnone@localhost:~$ fw_printenv | grep snap
loadfdt=fatload mmc ${mmcdev}:${mmcpart} ${fdtaddr} ${snap_kernel}/dtbs/${fdtfile}
loadinitrd=fatload mmc ${mmcdev}:${mmcpart} ${initrd_addr} ${snap_kernel}/${initrd_file}; setenv initrd_size ${filesize}
loadkernel=fatload mmc ${mmcdev}:${mmcpart} ${kernel_addr} ${snap_kernel}/${kernel_file}
mmcboot=run snappy_boot
mmcload=mmc rescan;run loadinitrd;${mmcloadcmd} mmc 0:${mmcloadpart} ${loadaddr} ${snap_kernel}/${bootimage};${mmcloadcmd} mmc 0:${mmcloadpart} ${fdtaddr} ${snap_kernel}/dtbs/${fdtimage}
snap_core=core_1580.snap
snap_kernel=dac-cpu-kernel_x1.snap
snappy_boot=if test "${snap_mode}" = "try"; then setenv snap_mode "trying"; saveenv; if test "${snap_try_core}" != ""; then setenv snap_core "${snap_try_core}"; fi; if test "${snap_try_kernel}" != ""; then setenv snap_kernel "${snap_try_kernel}"; fi; elif test "${snap_mode}" = "trying"; then setenv snap_mode ""; saveenv; fi; run loadfiles; setenv mmcroot "/dev/disk/by-label/writable ${snappy_cmdline} snap_core=${snap_core} snap_kernel=${snap_kernel}"; run mmcargs; bootz ${kernel_addr} - ${fdtaddr}
snappy_cmdline=net.ifnames=0 init=/lib/systemd/systemd ro panic=-1 fixrtc
snappy_mode=regular
snappy_trial_boot=0

Well, now trying to refresh from stable 1580 -> candidate 1690.

May 01 17:52:20 localhost.localdomain /usr/lib/snapd/snapd[1023]: daemon.go:176: DEBUG: uid=1000;@ POST /v2/snaps/core 1.356190923s 202
May 01 17:52:20 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 72 on Do: Download snap "core" (1690) from channel "candidate"
May 01 17:52:30 localhost.localdomain sudo[2342]: denisnone : TTY=pts/1 ; PWD=/home/denisnone ; USER=root ; COMMAND=/bin/journalctl -f
May 01 17:52:30 localhost.localdomain sudo[2342]: pam_unix(sudo:session): session opened for user root by denisnone(uid=0)
May 01 17:53:09 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 73 on Do: Fetch and check assertions for snap "core" (1690)
May 01 17:53:28 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 74 on Do: Mount snap "core" (1690)
May 01 17:53:28 localhost.localdomain systemd[1]: Reloading.
May 01 17:53:29 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 2h 28min 58.526034s random time.
May 01 17:53:29 localhost.localdomain systemd[1]: Reloading.
May 01 17:53:29 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 5h 15min 28.810924s random time.
May 01 17:53:29 localhost.localdomain systemd[1]: Mounting Mount unit for core...
May 01 17:53:29 localhost.localdomain systemd-udevd[705]: Network interface NamePolicy= disabled on kernel command line, ignoring.
May 01 17:53:30 localhost.localdomain systemd[1]: Mounted Mount unit for core.
May 01 17:53:30 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 75 on Do: Stop snap "core" services
May 01 17:53:30 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 76 on Do: Remove aliases for snap "core"
May 01 17:53:30 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 77 on Do: Make current revision for snap "core" unavailable
May 01 17:53:30 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 78 on Do: Copy snap "core" data
May 01 17:53:31 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 79 on Do: Setup snap "core" (1690) security profiles
May 01 17:53:31 localhost.localdomain /usr/lib/snapd/snapd[1023]: helpers.go:173: cannot connect plug "core-support" from snap "core", no such plug
May 01 17:53:31 localhost.localdomain snapd[1023]: 2017/05/01 17:53:31.172937 helpers.go:173: cannot connect plug "core-support" from snap "core", no such plug
May 01 17:53:31 localhost.localdomain /usr/lib/snapd/snapd[1023]: helpers.go:173: cannot connect plug "network-bind" from snap "core", no such plug
May 01 17:53:31 localhost.localdomain snapd[1023]: 2017/05/01 17:53:31.175301 helpers.go:173: cannot connect plug "network-bind" from snap "core", no such plug
May 01 17:53:31 localhost.localdomain audit[2423]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.core.hook.configure" pid=2423 comm="apparmor_parser"
May 01 17:53:31 localhost.localdomain kernel: audit: type=1400 audit(1493661211.868:47): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.core.hook.configure" pid=2423 comm="apparmor_parser"
May 01 17:53:31 localhost.localdomain audit[2425]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aconnect" pid=2425 comm="apparmor_parser"
May 01 17:53:31 localhost.localdomain kernel: audit: type=1400 audit(1493661211.951:48): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aconnect" pid=2425 comm="apparmor_parser"
May 01 17:53:31 localhost.localdomain audit[2427]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsa-restore" pid=2427 comm="apparmor_parser"
May 01 17:53:31 localhost.localdomain kernel: audit: type=1400 audit(1493661211.972:49): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsa-restore" pid=2427 comm="apparmor_parser"
May 01 17:53:31 localhost.localdomain audit[2429]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsabat" pid=2429 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain kernel: audit: type=1400 audit(1493661211.998:50): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsabat" pid=2429 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2431]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsactl" pid=2431 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain kernel: audit: type=1400 audit(1493661212.021:51): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsactl" pid=2431 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2433]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaloop" pid=2433 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain kernel: audit: type=1400 audit(1493661212.042:52): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaloop" pid=2433 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2435]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsamixer" pid=2435 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain kernel: audit: type=1400 audit(1493661212.065:53): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsamixer" pid=2435 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2437]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsatplg" pid=2437 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain kernel: audit: type=1400 audit(1493661212.086:54): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsatplg" pid=2437 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2439]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaucm" pid=2439 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain kernel: audit: type=1400 audit(1493661212.112:55): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaucm" pid=2439 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain kernel: audit: type=1400 audit(1493661212.133:56): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.amidi" pid=2441 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2441]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.amidi" pid=2441 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2443]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.amixer" pid=2443 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2445]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aplay" pid=2445 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2447]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aplaymidi" pid=2447 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2449]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.arecord" pid=2449 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2451]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.arecordmidi" pid=2451 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2453]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aseqdump" pid=2453 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2455]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aseqnet" pid=2455 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2457]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.iecset" pid=2457 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2459]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.speaker-test" pid=2459 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2461]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.avahi-daemon" pid=2461 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2463]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.help" pid=2463 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2465]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.hook.configure" pid=2465 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain audit[2467]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.restart-avahi-daemon" pid=2467 comm="apparmor_parser"
May 01 17:53:32 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 80 on Do: Make snap "core" (1690) available to the system
May 01 17:53:32 localhost.localdomain /usr/lib/snapd/snapd[1023]: task.go:303: DEBUG: 2017-05-01T17:53:32Z INFO Requested system restart.

Broadcast message from root@localhost.localdomain (Mon 2017-05-01 17:53:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!

May 01 17:53:32 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 81 on Do: Setup snap "core" (1690) security profiles (phase 2)
May 01 17:53:32 localhost.localdomain /usr/lib/snapd/snapd[1023]: task.go:303: DEBUG: 2017-05-01T17:53:32Z INFO Waiting for restart...

Broadcast message from root@localhost.localdomain (Mon 2017-05-01 17:54:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!


Broadcast message from root@localhost.localdomain (Mon 2017-05-01 17:55:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!


Broadcast message from root@localhost.localdomain (Mon 2017-05-01 17:56:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!


Broadcast message from root@localhost.localdomain (Mon 2017-05-01 17:57:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!


Broadcast message from root@localhost.localdomain (Mon 2017-05-01 17:58:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!

May 01 17:58:32 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 81 on Doing: Setup snap "core" (1690) security profiles (phase 2)
May 01 17:58:32 localhost.localdomain /usr/lib/snapd/snapd[1023]: task.go:303: DEBUG: 2017-05-01T17:58:32Z INFO Waiting for restart...
May 01 17:58:32 localhost.localdomain systemd-logind[1017]: Creating /run/nologin, blocking further logins...

Broadcast message from root@localhost.localdomain (Mon 2017-05-01 17:59:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!


Broadcast message from root@localhost.localdomain (Mon 2017-05-01 18:00:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!

May 01 18:00:59 localhost.localdomain /usr/lib/snapd/snapd[1023]: taskrunner.go:353: DEBUG: Running task 81 on Doing: Setup snap "core" (1690) security profiles (phase 2)
May 01 18:00:59 localhost.localdomain /usr/lib/snapd/snapd[1023]: task.go:303: DEBUG: 2017-05-01T18:00:59Z INFO Waiting for restart...
May 01 18:00:59 localhost.localdomain sshd[2470]: fatal: Access denied for user denisnone by PAM account configuration [preauth]

Broadcast message from root@localhost.localdomain (Mon 2017-05-01 18:01:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!


Broadcast message from root@localhost.localdomain (Mon 2017-05-01 18:02:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot at Mon 2017-05-01 18:03:32 UTC!


Broadcast message from root@localhost.localdomain (Mon 2017-05-01 18:03:32 UTC):

reboot scheduled to update the system - temporarily cancel with 'sudo shutdown -c'
The system is going down for reboot NOW!

Connection to 192.168.10.43 closed by remote host.
Connection to 192.168.10.43 closed.

denis · May 1, 2017, 6:58pm

After reboot I have this:

May 01 16:56:02 localhost.localdomain systemd[1]: Started LSB: AppArmor initialization.
May 01 16:56:02 localhost.localdomain systemd[1]: Starting Raise network interfaces...
May 01 16:56:02 localhost.localdomain systemd[1]: Reached target System Initialization.
May 01 16:56:02 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 41min 56.978812s random time.
May 01 16:56:02 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 4h 39.446974s random time.
May 01 16:56:02 localhost.localdomain systemd[1]: Started Timer to automatically refresh installed snaps.
May 01 16:56:02 localhost.localdomain systemd[1]: Started Trigger resolvconf update for networkd DNS.
May 01 16:56:02 localhost.localdomain systemd[1]: Reached target Paths.
May 01 16:56:02 localhost.localdomain systemd[1]: Starting Socket activation for snappy daemon.
May 01 16:56:02 localhost.localdomain systemd[1]: Listening on D-Bus System Message Bus Socket.
May 01 16:56:02 localhost.localdomain systemd[1]: Started Daily Cleanup of Temporary Directories.
May 01 16:56:02 localhost.localdomain systemd[1]: Reached target Timers.
May 01 16:56:02 localhost.localdomain systemd[1]: Listening on Socket activation for snappy daemon.
May 01 16:56:02 localhost.localdomain systemd[1]: Reached target Sockets.
May 01 16:56:02 localhost.localdomain systemd[1]: Reached target Basic System.
May 01 16:56:02 localhost.localdomain systemd[1]: Started Regular background program processing daemon.
May 01 16:56:02 localhost.localdomain systemd[1]: Starting Generate sshd host keys...
May 01 16:56:02 localhost.localdomain systemd[1]: Starting Login Service...
May 01 16:56:02 localhost.localdomain systemd[1]: Starting Permit User Sessions...
May 01 16:56:02 localhost.localdomain cron[859]: (CRON) INFO (pidfile fd = 3)
May 01 16:56:02 localhost.localdomain systemd[1]: Started D-Bus System Message Bus.
May 01 16:56:02 localhost.localdomain cron[859]: (CRON) INFO (Running @reboot jobs)
May 01 16:56:03 localhost.localdomain dbus[870]: [system] AppArmor D-Bus mediation is enabled
May 01 16:56:03 localhost.localdomain dbus[870]: [system] Successfully activated service 'org.freedesktop.systemd1'
May 01 16:56:03 localhost.localdomain systemd[1]: Starting Network Service...
May 01 16:56:03 localhost.localdomain systemd[1]: Started Cgroup management daemon.
May 01 16:56:03 localhost.localdomain systemd[1]: Starting System Logging Service...
May 01 16:56:03 localhost.localdomain systemd[1]: Starting Restore /etc/resolv.conf if the system crashed before the ppp link was shut down...
May 01 16:56:03 localhost.localdomain systemd[1]: Starting LSB: Set the CPU Frequency Scaling governor to "ondemand"...
May 01 16:56:03 localhost.localdomain systemd[1]: Started Snappy daemon.
May 01 16:56:03 localhost.localdomain systemd[1]: Starting Auto import assertions from block devices...
May 01 16:56:03 localhost.localdomain systemd[1]: Started Permit User Sessions.
May 01 16:56:03 localhost.localdomain systemd[1]: Started Restore /etc/resolv.conf if the system crashed before the ppp link was shut down.
May 01 16:56:03 localhost.localdomain kernel: cgroup: new mount options do not match the existing superblock, will be ignored
May 01 16:56:03 localhost.localdomain systemd[1]: Started Generate sshd host keys.
May 01 16:56:03 localhost.localdomain systemd[1]: Started Auto import assertions from block devices.
May 01 16:56:03 localhost.localdomain systemd-networkd[890]: Enumeration completed
May 01 16:56:03 localhost.localdomain systemd-networkd[890]: eth0: IPv6 enabled for interface: Success
May 01 16:56:03 localhost.localdomain systemd[1]: Started Network Service.
May 01 16:56:03 localhost.localdomain systemd[1]: Started System Logging Service.
May 01 16:56:03 localhost.localdomain kernel: socfpga-dwmac ff702000.ethernet eth0: IEEE 1588-2008 Advanced Timestamp supported
May 01 16:56:03 localhost.localdomain kernel: socfpga-dwmac ff702000.ethernet eth0: registered PTP clock
May 01 16:56:03 localhost.localdomain kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
May 01 16:56:03 localhost.localdomain systemd-logind[865]: New seat seat0.
May 01 16:56:03 localhost.localdomain systemd[1]: Started Login Service.
May 01 16:56:03 localhost.localdomain systemd[1]: Started LSB: Set the CPU Frequency Scaling governor to "ondemand".
May 01 16:56:04 localhost.localdomain systemd[1]: Starting Update resolvconf for networkd DNS...
May 01 16:56:04 localhost.localdomain systemd[1]: Starting Wait for Network to be Configured...
May 01 16:56:04 localhost.localdomain systemd[1]: Starting Set console scheme...
May 01 16:56:04 localhost.localdomain systemd[1]: Started Raise network interfaces.
May 01 16:56:04 localhost.localdomain systemd[1]: Started Set console scheme.
May 01 16:56:04 localhost.localdomain systemd-networkd-wait-online[938]: ignoring: lo
May 01 16:56:04 localhost.localdomain systemd[1]: Reached target Network.
May 01 16:56:04 localhost.localdomain systemd[1]: Starting OpenBSD Secure Shell server...
May 01 16:56:04 localhost.localdomain sh[937]: sed: can't read /run/systemd/netif/leases/*: No such file or directory
May 01 16:56:04 localhost.localdomain sshd[948]: Server listening on 0.0.0.0 port 22.
May 01 16:56:04 localhost.localdomain systemd[1]: Started OpenBSD Secure Shell server.
May 01 16:56:04 localhost.localdomain sshd[948]: Server listening on :: port 22.
May 01 16:56:05 localhost.localdomain sh[937]: sed: can't read /run/systemd/netif/leases/*: No such file or directory
May 01 16:56:05 localhost.localdomain /usr/lib/snapd/snapd[897]: snapmgr.go:309: DEBUG: snapmgr refresh randomness 55m21.259472707s
May 01 16:56:05 localhost.localdomain /usr/lib/snapd/snapd[897]: helpers.go:173: cannot connect plug "core-support" from snap "core", no such plug
May 01 16:56:05 localhost.localdomain /usr/lib/snapd/snapd[897]: helpers.go:173: cannot connect plug "network-bind" from snap "core", no such plug
May 01 16:56:05 localhost.localdomain snapd[897]: 2017/05/01 16:56:05.505330 helpers.go:173: cannot connect plug "core-support" from snap "core", no such plug
May 01 16:56:05 localhost.localdomain snapd[897]: 2017/05/01 16:56:05.506017 helpers.go:173: cannot connect plug "network-bind" from snap "core", no such plug
May 01 16:56:05 localhost.localdomain kernel: random: crng init done
May 01 16:56:05 localhost.localdomain audit[960]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aconnect" pid=960 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[963]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsa-restore" pid=963 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[965]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsabat" pid=965 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[967]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsactl" pid=967 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[969]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaloop" pid=969 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[971]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsamixer" pid=971 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[973]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsatplg" pid=973 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[975]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaucm" pid=975 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[977]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.amidi" pid=977 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[979]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.amixer" pid=979 comm="apparmor_parser"
May 01 16:56:05 localhost.localdomain audit[981]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aplay" pid=981 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[983]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aplaymidi" pid=983 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[985]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.arecord" pid=985 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[987]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.arecordmidi" pid=987 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[989]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aseqdump" pid=989 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[991]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aseqnet" pid=991 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[993]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.iecset" pid=993 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[995]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.speaker-test" pid=995 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain sh[937]: sed: can't read /run/systemd/netif/leases/*: No such file or directory
May 01 16:56:06 localhost.localdomain audit[1001]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.avahi-daemon" pid=1001 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[1003]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.help" pid=1003 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[1005]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.hook.configure" pid=1005 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[1007]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.restart-avahi-daemon" pid=1007 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[1009]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.core.hook.configure" pid=1009 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[1011]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.dac-cpu.hook.prepare-device" pid=1011 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain audit[1013]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.htop.htop" pid=1013 comm="apparmor_parser"
May 01 16:56:06 localhost.localdomain /usr/lib/snapd/snapd[897]: daemon.go:250: DEBUG: init done in 4.86119ms
May 01 16:56:06 localhost.localdomain /usr/lib/snapd/snapd[897]: daemon.go:251: started snapd/2.24 (series 16) ubuntu-core/16 (armhf) linux/4.10.1-dac_cpu.
May 01 16:56:06 localhost.localdomain snapd[897]: 2017/05/01 16:56:06.927277 daemon.go:251: started snapd/2.24 (series 16) ubuntu-core/16 (armhf) linux/4.10.1-dac_cpu.
May 01 16:56:06 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 87 on Do: Run prepare-device hook
May 01 16:56:07 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 81 on Doing: Setup snap "core" (1690) security profiles (phase 2)
May 01 16:56:07 localhost.localdomain /usr/lib/snapd/snapd[897]: stateengine.go:98: state ensure error: devicemgr: snap "core" has changes in progress
May 01 16:56:07 localhost.localdomain snapd[897]: 2017/05/01 16:56:07.249027 stateengine.go:98: state ensure error: devicemgr: snap "core" has changes in progress
May 01 16:56:07 localhost.localdomain sh[937]: sed: can't read /run/systemd/netif/leases/*: No such file or directory
May 01 16:56:07 localhost.localdomain /usr/lib/snapd/snapd[897]: task.go:303: DEBUG: 2017-05-01T16:56:07Z ERROR cannot finish core installation, there was a rollback across reboot
May 01 16:56:07 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 80 on Undo: Make snap "core" (1690) available to the system
May 01 16:56:07 localhost.localdomain /usr/lib/snapd/snapd[897]: stateengine.go:98: state ensure error: devicemgr: snap "core" has changes in progress
May 01 16:56:07 localhost.localdomain snapd[897]: 2017/05/01 16:56:07.710730 stateengine.go:98: state ensure error: devicemgr: snap "core" has changes in progress
May 01 16:56:07 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 72 on Undo: Download snap "core" (1690) from channel "candidate"
May 01 16:56:07 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 79 on Undo: Setup snap "core" (1690) security profiles
May 01 16:56:08 localhost.localdomain kernel: socfpga-dwmac ff702000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx
May 01 16:56:08 localhost.localdomain kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
May 01 16:56:08 localhost.localdomain systemd-networkd[890]: eth0: Gained carrier
May 01 16:56:08 localhost.localdomain systemd-networkd-wait-online[938]: ignoring: lo
May 01 16:56:08 localhost.localdomain systemd-networkd-wait-online[938]: ignoring: lo
May 01 16:56:08 localhost.localdomain systemd-networkd[890]: eth0: DHCPv4 address 192.168.10.43/24 via 192.168.10.1
May 01 16:56:08 localhost.localdomain systemd-networkd-wait-online[938]: ignoring: lo
May 01 16:56:08 localhost.localdomain systemd-timesyncd[713]: Network configuration changed, trying to establish connection.
May 01 16:56:08 localhost.localdomain systemd-networkd-wait-online[938]: ignoring: lo
May 01 16:56:08 localhost.localdomain /usr/lib/snapd/snapd[897]: helpers.go:173: cannot connect plug "core-support" from snap "core", no such plug
May 01 16:56:08 localhost.localdomain snapd[897]: 2017/05/01 16:56:08.058630 helpers.go:173: cannot connect plug "core-support" from snap "core", no such plug
May 01 16:56:08 localhost.localdomain /usr/lib/snapd/snapd[897]: helpers.go:173: cannot connect plug "network-bind" from snap "core", no such plug
May 01 16:56:08 localhost.localdomain snapd[897]: 2017/05/01 16:56:08.061630 helpers.go:173: cannot connect plug "network-bind" from snap "core", no such plug
May 01 16:56:08 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 88 on Do: Generate device key
May 01 16:56:08 localhost.localdomain audit[1032]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.core.hook.configure" pid=1032 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: kauditd_printk_skb: 138 callbacks suppressed
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.212:58): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.core.hook.configure" pid=1032 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain /usr/lib/snapd/snapd[897]: handlers.go:205: DEBUG: Cannot report problem: Post https://daisy.ubuntu.com//f67210db41e7db9276eb99a408cc9c3ef497c0345d4fd6bed173c8bb4b43a12b991eccd3aca2c1702b1f037bb049243aaddde4faa2c02d16216d23edec9b9cdf: dial tcp: lookup daisy.ubuntu.com on [::1]:53: read udp [::1]:33749->[::1]:53: read: connection refused
May 01 16:56:08 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 89 on Do: Request device serial
May 01 16:56:08 localhost.localdomain /usr/lib/snapd/snapd[897]: task.go:303: DEBUG: 2017-05-01T16:56:08Z ERROR cannot retrieve request-id for making a request for a serial: Post https://myapps.developer.ubuntu.com/identity/api/v1/request-id: dial tcp: lookup myapps.developer.ubuntu.com on [::1]:53: read udp [::1]:38992->[::1]:53: read: connection refused
May 01 16:56:08 localhost.localdomain systemd[1]: Started Update resolvconf for networkd DNS.
May 01 16:56:08 localhost.localdomain audit[1060]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aconnect" pid=1060 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.649:59): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aconnect" pid=1060 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1062]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsa-restore" pid=1062 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.670:60): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsa-restore" pid=1062 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1064]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsabat" pid=1064 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.691:61): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsabat" pid=1064 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1066]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsactl" pid=1066 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.712:62): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsactl" pid=1066 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1068]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaloop" pid=1068 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.733:63): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaloop" pid=1068 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1070]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsamixer" pid=1070 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.754:64): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsamixer" pid=1070 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1072]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsatplg" pid=1072 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.775:65): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsatplg" pid=1072 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1074]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaucm" pid=1074 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.796:66): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.alsaucm" pid=1074 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1076]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.amidi" pid=1076 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain kernel: audit: type=1400 audit(1493657768.819:67): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.amidi" pid=1076 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1078]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.amixer" pid=1078 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1080]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aplay" pid=1080 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1082]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aplaymidi" pid=1082 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1084]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.arecord" pid=1084 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1086]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.arecordmidi" pid=1086 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1088]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aseqdump" pid=1088 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1090]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.aseqnet" pid=1090 comm="apparmor_parser"
May 01 16:56:08 localhost.localdomain audit[1092]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.iecset" pid=1092 comm="apparmor_parser"
May 01 16:56:09 localhost.localdomain audit[1094]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.alsa-utils.speaker-test" pid=1094 comm="apparmor_parser"
May 01 16:56:09 localhost.localdomain audit[1096]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.avahi-daemon" pid=1096 comm="apparmor_parser"
May 01 16:56:09 localhost.localdomain audit[1098]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.help" pid=1098 comm="apparmor_parser"
May 01 16:56:09 localhost.localdomain audit[1100]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.hook.configure" pid=1100 comm="apparmor_parser"
May 01 16:56:09 localhost.localdomain audit[1102]: AVC apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.avahi.restart-avahi-daemon" pid=1102 comm="apparmor_parser"
May 01 16:56:09 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 78 on Undo: Copy snap "core" data
May 01 16:56:09 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 77 on Undo: Make current revision for snap "core" unavailable
May 01 16:56:09 localhost.localdomain systemd-networkd[890]: eth0: Gained IPv6LL
May 01 16:56:09 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 76 on Undo: Remove aliases for snap "core"
May 01 16:56:09 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 75 on Undo: Stop snap "core" services
May 01 16:56:09 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 74 on Undo: Mount snap "core" (1690)
May 01 16:56:10 localhost.localdomain systemd[1]: Unmounted Mount unit for core.
May 01 16:56:10 localhost.localdomain systemd[1]: Reloading.
May 01 16:56:10 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 3h 5min 11.106388s random time.
May 01 16:56:10 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 4h 31min 899.926ms random time.
May 01 16:56:10 localhost.localdomain systemd[1]: Reloading.
May 01 16:56:11 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 3h 56min 46.409345s random time.
May 01 16:56:11 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 1h 28min 38.295789s random time.
May 01 16:56:22 localhost.localdomain systemd-networkd[890]: eth0: Configured
May 01 16:56:22 localhost.localdomain systemd-timesyncd[713]: Network configuration changed, trying to establish connection.
May 01 16:56:22 localhost.localdomain systemd-networkd-wait-online[938]: ignoring: lo
May 01 16:56:22 localhost.localdomain systemd[1]: Started Wait for Network to be Configured.
May 01 16:56:22 localhost.localdomain systemd[1]: Starting Update resolvconf for networkd DNS...
May 01 16:56:22 localhost.localdomain systemd[1]: Reached target Network is Online.
May 01 16:56:22 localhost.localdomain systemd[1]: Started Service for snap application avahi.avahi-daemon.
May 01 18:04:23 localhost.localdomain systemd-timesyncd[713]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
May 01 18:04:23 localhost.localdomain systemd[1]: Starting Ubuntu FAN network setup...
May 01 18:04:23 localhost.localdomain systemd[1]: Starting /etc/rc.local Compatibility...
May 01 18:04:23 localhost.localdomain systemd[1]: Started Service for snap application alsa-utils.alsa-restore.
May 01 18:04:23 localhost.localdomain snap[1147]: avahi-daemon 0.6.32 starting up.
May 01 18:04:23 localhost.localdomain snap[1147]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
May 01 18:04:23 localhost.localdomain snap[1147]: Loading service file /var/snap/avahi/common/etc/avahi/services/sftp-ssh.service.
May 01 18:04:23 localhost.localdomain snap[1147]: Loading service file /var/snap/avahi/common/etc/avahi/services/ssh.service.
May 01 18:04:23 localhost.localdomain snap[1147]: System host name is set to 'localhost'. This is not a suitable mDNS host name, looking for alternatives.
May 01 18:04:23 localhost.localdomain systemd[1]: Started Update resolvconf for networkd DNS.
May 01 18:04:23 localhost.localdomain snap[1147]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::207:edff:fe4b:5318.
May 01 18:04:23 localhost.localdomain snap[1147]: New relevant interface eth0.IPv6 for mDNS.
May 01 18:04:23 localhost.localdomain snap[1147]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.10.43.
May 01 18:04:23 localhost.localdomain snap[1147]: New relevant interface eth0.IPv4 for mDNS.
May 01 18:04:23 localhost.localdomain snap[1147]: Network interface enumeration completed.
May 01 18:04:23 localhost.localdomain snap[1147]: Registering new address record for 192.168.10.43 on eth0.IPv4.
May 01 18:04:23 localhost.localdomain systemd[1]: Started Ubuntu FAN network setup.
May 01 18:04:23 localhost.localdomain systemd[1]: Started /etc/rc.local Compatibility.
May 01 18:04:23 localhost.localdomain systemd[1]: Time has been changed
May 01 18:04:23 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 5h 6min 50.756481s random time.
May 01 18:04:23 localhost.localdomain systemd[1]: snapd.refresh.timer: Adding 4h 21min 33.873622s random time.
May 01 18:04:23 localhost.localdomain systemd[1]: Started Serial Getty on ttyS0.
May 01 18:04:23 localhost.localdomain systemd[1]: Started Getty on tty1.
May 01 18:04:23 localhost.localdomain systemd[1]: Reached target Login Prompts.
May 01 18:04:23 localhost.localdomain systemd[1]: Reached target Multi-User System.
May 01 18:04:23 localhost.localdomain systemd[1]: Reached target Graphical Interface.
May 01 18:04:23 localhost.localdomain systemd[1]: Starting Update UTMP about System Runlevel Changes...
May 01 18:04:23 localhost.localdomain systemd[1]: Started Update UTMP about System Runlevel Changes.
May 01 18:04:23 localhost.localdomain systemd[1]: Startup finished in 4.577s (kernel) + 29.110s (userspace) = 33.688s.
May 01 18:04:23 localhost.localdomain systemd[1]: Created slice system-serial\x2dconsole\x2dconf.slice.
May 01 18:04:23 localhost.localdomain systemd[1]: Started Ubuntu Core Firstboot Configuration ttyS0.
May 01 18:04:23 localhost.localdomain systemd[1]: Created slice system-console\x2dconf.slice.
May 01 18:04:24 localhost.localdomain systemd[1]: Started Ubuntu Core Firstboot Configuration tty1.
May 01 18:04:24 localhost.localdomain systemd[1]: Stopping Getty on tty1...
May 01 18:04:24 localhost.localdomain systemd[1]: Stopping Serial Getty on ttyS0...
May 01 18:04:24 localhost.localdomain systemd[1]: Stopped Serial Getty on ttyS0.
May 01 18:04:24 localhost.localdomain systemd[1]: Stopped Getty on tty1.
May 01 18:04:24 localhost.localdomain /usr/lib/snapd/snapd[897]: daemon.go:176: DEBUG: uid=0;@ GET /v2/system-info 2.2153ms 200
May 01 18:04:24 localhost.localdomain /usr/lib/snapd/snapd[897]: daemon.go:176: DEBUG: uid=0;@ GET /v2/system-info 765.58µs 200
May 01 18:04:24 localhost.localdomain snap[1147]: Server startup complete. Host name is ubuntucore.local. Local service cookie is 2644457387.
May 01 18:04:25 localhost.localdomain snap[1147]: Service "ubuntucore" (/var/snap/avahi/common/etc/avahi/services/ssh.service) successfully established.
May 01 18:04:25 localhost.localdomain snap[1147]: Service "ubuntucore" (/var/snap/avahi/common/etc/avahi/services/sftp-ssh.service) successfully established.
May 01 18:05:09 localhost.localdomain /usr/lib/snapd/snapd[897]: taskrunner.go:367: DEBUG: Running task 89 on Doing: Request device serial
May 01 18:05:12 localhost.localdomain /usr/lib/snapd/snapd[897]: task.go:303: DEBUG: 2017-05-01T18:05:12Z ERROR cannot deliver device serial request: Cannot process serial request for device with brand « u***wrSD", store can sign serial only for brand "canonical"
May 01 18:06:39 localhost.localdomain sshd[1253]: Accepted publickey for denisnone from ***
May 01 18:06:39 localhost.localdomain sshd[1253]: pam_unix(sshd:session): session opened for user denisnone by (uid=0)
May 01 18:06:39 localhost.localdomain systemd[1]: Created slice User Slice of denisnone.
May 01 18:06:39 localhost.localdomain systemd[1]: Starting User Manager for UID 1000...
May 01 18:06:39 localhost.localdomain systemd-logind[865]: New session 1 of user denisnone.
May 01 18:06:39 localhost.localdomain systemd[1]: Started Session 1 of user denisnone.
May 01 18:06:39 localhost.localdomain systemd[1255]: pam_unix(systemd-user:session): session opened for user denisnone by (uid=0)
May 01 18:06:39 localhost.localdomain systemd[1255]: Reached target Timers.
May 01 18:06:39 localhost.localdomain systemd[1255]: Reached target Sockets.
May 01 18:06:39 localhost.localdomain systemd[1255]: Reached target Paths.
May 01 18:06:39 localhost.localdomain systemd[1255]: Reached target Basic System.
May 01 18:06:39 localhost.localdomain systemd[1255]: Reached target Default.
May 01 18:06:39 localhost.localdomain systemd[1255]: Startup finished in 196ms.
May 01 18:06:39 localhost.localdomain systemd[1]: Started User Manager for UID 1000.
May 01 18:06:45 localhost.localdomain sudo[1282]: denisnone : TTY=pts/0 ; PWD=/home/denisnone ; USER=root ; COMMAND=/bin/journalctl -b
May 01 18:06:45 localhost.localdomain sudo[1282]: pam_unix(sudo:session): session opened for user root by denisnone(uid=0)
May 01 18:07:15 localhost.localdomain sudo[1282]: pam_unix(sudo:session): session closed for user root
May 01 18:07:19 localhost.localdomain sudo[1285]: denisnone : TTY=pts/0 ; PWD=/home/denisnone ; USER=root ; COMMAND=/bin/journalctl -b
May 01 18:07:19 localhost.localdomain sudo[1285]: pam_unix(sudo:session): session opened for user root by denisnone(uid=0)

denis · May 1, 2017, 6:58pm

And finally new uboot envs:

denisnone@localhost:~$ fw_printenv | grep snap
loadfdt=fatload mmc ${mmcdev}:${mmcpart} ${fdtaddr} ${snap_kernel}/dtbs/${fdtfile}
loadinitrd=fatload mmc ${mmcdev}:${mmcpart} ${initrd_addr} ${snap_kernel}/${initrd_file}; setenv initrd_size ${filesize}
loadkernel=fatload mmc ${mmcdev}:${mmcpart} ${kernel_addr} ${snap_kernel}/${kernel_file}
mmcboot=run snappy_boot
mmcload=mmc rescan;run loadinitrd;${mmcloadcmd} mmc 0:${mmcloadpart} ${loadaddr} ${snap_kernel}/${bootimage};${mmcloadcmd} mmc 0:${mmcloadpart} ${fdtaddr} ${snap_kernel}/dtbs/${fdtimage}
snap_core=core_1580.snap
snap_kernel=dac-cpu-kernel_x1.snap
snap_mode=try
snap_try_core=core_1690.snap
snappy_boot=if test "${snap_mode}" = "try"; then setenv snap_mode "trying"; saveenv; if test "${snap_try_core}" != ""; then setenv snap_core "${snap_try_core}"; fi; if test "${snap_try_kernel}" != ""; then setenv snap_kernel "${snap_try_kernel}"; fi; elif test "${snap_mode}" = "trying"; then setenv snap_mode ""; saveenv; fi; run loadfiles; setenv mmcroot "/dev/disk/by-label/writable ${snappy_cmdline} snap_core=${snap_core} snap_kernel=${snap_kernel}"; run mmcargs; bootz ${kernel_addr} - ${fdtaddr}
snappy_cmdline=net.ifnames=0 init=/lib/systemd/systemd ro panic=-1 fixrtc
snappy_mode=regular
snappy_trial_boot=0

niemeyer · May 1, 2017, 7:18pm

@denis Thanks for all those details. I’ve changed these posts slightly to use pre-formatted boxes so that the content looks more readable in the forum. In the future, when you have so much volume of data it’s best to use a paste service (gist, for example) and link here so that the conversation itself isn’t compromises by the volume of information provided.

denis · May 1, 2017, 7:37pm

Thanks @niemeyer. I tried to use “hide detail” macro, it shows well in preview but then when posted it doesn’t work. Next time I’ll try boxes and paste services.

ogra · May 2, 2017, 11:38am

i have filed https://bugs.launchpad.net/snapd/+bug/1687608 for the pi3 issue you mentioned above (since we are discussing two different things in this thread, lets focus on your bricking issue here and treat the pi3 bug as a bug)

ogra · May 2, 2017, 12:46pm

going back to your initial post, here is my theory what happens:

you refresh core … it puts the new snap in place, sets “snap_mode=try” and “snap_try_core=core_1805.snap” …

it reboots into the new setup, finds core_1805 unsuitable for whatever reason (to be determined) and removes the snap from disk, but here snapd fails to unset “snap_mode” and “snap_try_core” (also to be determined)

you do the manual reboot with these vars still set, the system does not find the snap file despite “snap_core” on the kernel cmdline pointing to it which makes you end up in the initrd.

your uboot vars in the second post seem to show the same behaviour, i assume you did not do a manual reboot there yet ?

zyga-snapd · May 2, 2017, 1:05pm

Can you please say what does snap version say?

denis · May 2, 2017, 1:35pm

What I’ve found so far:
uboot is configured to save environment variables not on mmc/fat but to mmc at offset 512 just after MBR.
When I initially worked on that, I found that I can’t let it save to FAT because I have a version 2013, which ruins FAT partition when it writes to that. So I decided to let it save after MBR and restore variables from there, but then after boot delay, a boot script re-reads environment variables from file from FAT partition modifying old vars with those prepared by snapd. This is how new core_1805 is passed to kernel and I thought it would be a workaround.
But what happens then is that uboot sets “trying” variable but saves it as raw after MBR. If snapd senses for that “trying” on next boot and obviously it’s not in the file at FAT partition. And everything depends on what snapd does in that case.

I had plans on upgrading my uboot to version 2017, but I wanted to postpone it as far as I can. It’ll take some time as it involves also to prepare a SPL preloader as well. And SPL depends on some headers that are generated automatically based on SoC configuration which in turn depend on FPGA project. It may be a one-day deal or it can take one week, never know.

I will work on that in parallel with some other tasks. I’ll try first old 2013 SPL with new 2017 UBoot.

But still is it the cause of the problem? And not something else? Does snapd refuse to apply new Core because of “trying” or there is also something else in addition?

ogra · May 2, 2017, 2:00pm

snapd as well as ubuntu-image will only use the uboot.env file (for ubuntu-image this requires the uboot.conf link to point to it) … we picked this setup to avoid exactly the fat corruption with older uboot. due to the fact that the uboot.env is a pre-created binary blob file with a fixed size, it will never actually change on the fat.

changes are just atomic, bit wise modifications inside the fixed size file.

it should work just fine with your uboot whatever version it is. essential is that you set the right config options at build time like CONFIG_ENV_SIZE, CONFIG_ENV_IS_IN_FAT and CONFIG_SYS_REDUNDAND_ENVIRONMENT that you can see in our uboot.patch

denis · May 3, 2017, 11:23am

Thanks, @ogra, this works now. I used my U-Boot 2013.01.01 (May 02 2017 - 19:59:58) with your recommended CONFIGs from patch and rpi.h. Uboot reads envs, saves envs, snapd does the same. And finally Core snap gets really refreshed without problems. I can change channels now as on raspi3 now. (but snapd holds ssh session as usual, no surprise here ) The only thing bothers me is unaligned access when U-Boot reads envs on start. This looks like this:

reading uboot.env
FAT: Misaligned buffer address (3fed7738)
In:    serial
Out:   serial
Err:   serial

It doesn’t influence boot process but looks ugly. I will need to dig in there.

The versions are 2.24 and 2.25. All those Canonical supplied in stable-candidate-beta-edge channels this week

ogra · May 3, 2017, 1:14pm

take alook at https://bugs.launchpad.net/snapd/+bug/1687608
you can actually ctrl-c the UI (if you hit it a few times) to get your console back (note that you only stop the UI with this, snapd will move on operating)