search

eclipse-che / che

Kubernetes based Cloud Development Environments for Enterprise Teams
http://eclipse.org/che
Eclipse Public License 2.0
6.93k stars 1.18k forks source link

Can't reuse Che Artik IDE #1207

Closed HDC67 closed 8 years ago

HDC67 commented 8 years ago

Hi

I have successfully set up a Che using vagrant to create a VirtualBox VM from here https://eclipse-che.readme.io/v4.0/docs/samsung-artik-ide-getting-started . It boots and runs fine and is accessible on http://192.168.28.28:8080. No problem there.

However, if I suspend (vagrant suspend) and resume or restart the VM, I'm no longer able to access the IDE. Chrome just says the connection is refused. I can ping the IP but that's about all. I can't seem to find any reference as to what the root password would be so I can't log into the VM and check basics like firewalls, ports open etc.

This is the command prompt log from starting the IDE (where it doesn't work):

C:\Users\Downloads\CHE>vagrant up Bringing machine 'artik' up with 'virtualbox' provider... ==> artik: Clearing any previously set forwarded ports... ==> artik: Clearing any previously set network interfaces... ==> artik: Preparing network interfaces based on configuration... artik: Adapter 1: nat artik: Adapter 2: hostonly ==> artik: Forwarding ports... artik: 22 (guest) => 2222 (host) (adapter 1) ==> artik: Running 'pre-boot' VM customizations... ==> artik: Booting VM... ==> artik: Waiting for machine to boot. This may take a few minutes... artik: SSH address: 127.0.0.1:2222 artik: SSH username: vagrant artik: SSH auth method: private key artik: Warning: Remote connection disconnect. Retrying... artik: Warning: Remote connection disconnect. Retrying... artik: Warning: Remote connection disconnect. Retrying... ==> artik: Machine booted and ready! ==> artik: Checking for guest additions in VM... ==> artik: Configuring and enabling network interfaces... ==> artik: Mounting shared folders... artik: /vagrant => C:/Users//Downloads/CHE ==> artik: Machine already provisioned. Run vagrant provision or use the --provision ==> artik: flag to force provisioning. Provisioners marked to run always will still run. ==> artik: Running provisioner: shell... artik: Running: inline script ==> artik: . ==> artik: . ==> artik: ARTIK IDE: SERVER BOOTING ~10s ==> artik: AVAILABLE: http://192.168.28.28:8080 ==> artik: . ==> artik: .

If I then run vagrant provision (not sure if I should do that whilst the VM is on), it downloads the 91.5MB ARTIK IDE again, gives me the same details and I'm now able to use the IDE on the same IP, port etc as before. It seems to remember projects etc but I don't really like having to download that 91MB IDE every time and I'm sure it shouldn't need to do that. The command prompt log doesn't seem to give any indication as to what was wrong / fixed by provisioning again

C:\Users\Downloads\CHE>vagrant provision ==> artik: Running provisioner: shell... artik: Running: inline script ==> artik: . ==> artik: . ==> artik: ARTIK IDE: DOWNLOADING ARTIK IDE ==> artik: . ==> artik: . ==> artik: % Total % Received % Xferd Average Speed Time Time Time Current ==> artik: Dload Upload Total Spent Left Speed 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 0 0 0 0 0 0 0 0 --:--:-- 0:00:01 --:--:-- 0 0 91.5M 0 0 0 0 0 0 --:--:-- 0:00:01 --:--:-- 0 0 91.5M 0 98304 0 0 35939 0 0:44:32 0:00:02 0:44:30 35942 0 91.5M 0 320k 0 0 88322 0 0:18:07 0:00:03 0:18:04 88323 0 91.5M 0 832k 0 0 177k 0 0:08:47 0:00:04 0:08:43 177k 1 91.5M 1 1344k 0 0 236k 0 0:06:35 0:00:05 0:06:30 323k 2 91.5M 2 1920k 0 0 287k 0 0:05:25 0:00:06 0:05:19 390k 2 91.5M 2 2496k 0 0 325k 0 0:04:48 0:00:07 0:04:41 485k 3 91.5M 3 3088k 0 0 355k 0 0:04:23 0:00:08 0:04:15 557k 3 91.5M 3 3664k 0 0 378k 0 0:04:07 0:00:09 0:03:58 567k 4 91.5M 4 4272k 0 0 399k 0 0:03:55 0:00:10 0:03:45 581k 5 91.5M 5 4912k 0 0 420k 0 0:03:42 0:00:11 0:03:31 598k 6 91.5M 6 5664k 0 0 446k 0 0:03:29 0:00:12 0:03:17 634k 6 91.5M 6 6560k 0 0 478k 0 0:03:15 0:00:13 0:03:02 691k 8 91.5M 8 7664k 0 0 522k 0 0:02:59 0:00:14 0:02:45 800k 9 91.5M 9 9040k 0 0 576k 0 0:02:42 0:00:15 0:02:27 959k 10 91.5M 10 10.0M 0 0 616k 0 0:02:32 0:00:16 0:02:16 1072k 12 91.5M 12 11.3M 0 0 658k 0 0:02:22 0:00:17 0:02:05 1193k 13 91.5M 13 12.7M 0 0 700k 0 0:02:13 0:00:18 0:01:55 1311k 15 91.5M 15 13.9M 0 0 727k 0 0:02:08 0:00:19 0:01:49 1331k 16 91.5M 16 15.1M 0 0 750k 0 0:02:04 0:00:20 0:01:44 1296k 17 91.5M 17 16.4M 0 0 776k 0 0:02:00 0:00:21 0:01:39 1312k 19 91.5M 19 17.7M 0 0 801k 0 0:01:57 0:00:22 0:01:35 1308k 20 91.5M 20 19.0M 0 0 823k 0 0:01:53 0:00:23 0:01:30 1283k 21 91.5M 21 19.7M 0 0 819k 0 0:01:54 0:00:24 0:01:30 1177k 22 91.5M 22 20.6M 0 0 822k 0 0:01:54 0:00:25 0:01:29 1116k 23 91.5M 23 21.3M 0 0 819k 0 0:01:54 0:00:26 0:01:28 1008k 24 91.5M 24 22.1M 0 0 819k 0 0:01:54 0:00:27 0:01:27 902k 25 91.5M 25 22.9M 0 0 819k 0 0:01:54 0:00:28 0:01:26 799k 25 91.5M 25 23.7M 0 0 819k 0 0:01:54 0:00:29 0:01:25 823k 26 91.5M 26 24.5M 0 0 819k 0 0:01:54 0:00:30 0:01:24 806k 27 91.5M 27 25.3M 0 0 820k 0 0:01:54 0:00:31 0:01:23 825k 28 91.5M 28 26.2M 0 0 823k 0 0:01:53 0:00:32 0:01:21 845k 29 91.5M 29 27.3M 0 0 830k 0 0:01:52 0:00:33 0:01:19 893k 31 91.5M 31 28.5M 0 0 841k 0 0:01:51 0:00:34 0:01:17 971k 32 91.5M 32 29.8M 0 0 858k 0 0:01:49 0:00:35 0:01:14 1095k 33 91.5M 33 31.1M 0 0 868k 0 0:01:47 0:00:36 0:01:11 1171k 35 91.5M 35 32.4M 0 0 880k 0 0:01:46 0:00:37 0:01:09 1254k 36 91.5M 36 33.8M 0 0 896k 0 0:01:44 0:00:38 0:01:06 1337k 38 91.5M 38 34.9M 0 0 901k 0 0:01:44 0:00:39 0:01:05 1313k 39 91.5M 39 36.3M 0 0 915k 0 0:01:42 0:00:40 0:01:02 1327k 41 91.5M 41 37.6M 0 0 924k 0 0:01:41 0:00:41 0:01:00 1337k 42 91.5M 42 38.9M 0 0 935k 0 0:01:40 0:00:42 0:00:58 1344k 44 91.5M 44 40.3M 0 0 945k 0 0:01:39 0:00:43 0:00:56 1330k 45 91.5M 45 41.7M 0 0 955k 0 0:01:38 0:00:44 0:00:54 1390k 47 91.5M 47 43.0M 0 0 965k 0 0:01:37 0:00:45 0:00:52 1373k 48 91.5M 48 44.4M 0 0 975k 0 0:01:36 0:00:46 0:00:50 1395k 50 91.5M 50 45.8M 0 0 985k 0 0:01:35 0:00:47 0:00:48 1411k 51 91.5M 51 47.2M 0 0 994k 0 0:01:34 0:00:48 0:00:46 1421k 53 91.5M 53 48.5M 0 0 998k 0 0:01:33 0:00:49 0:00:44 1365k 54 91.5M 54 49.8M 0 0 1007k 0 0:01:33 0:00:50 0:00:43 1386k 55 91.5M 55 51.1M 0 0 1014k 0 0:01:32 0:00:51 0:00:41 1379k 57 91.5M 57 52.6M 0 0 1023k 0 0:01:31 0:00:52 0:00:39 1385k 59 91.5M 59 54.0M 0 0 1031k 0 0:01:30 0:00:53 0:00:37 1392k 60 91.5M 60 55.2M 0 0 1034k 0 0:01:30 0:00:54 0:00:36 1407k 61 91.5M 61 56.4M 0 0 1038k 0 0:01:30 0:00:55 0:00:35 1355k 63 91.5M 63 57.7M 0 0 1044k 0 0:01:29 0:00:56 0:00:33 1350k 64 91.5M 64 59.1M 0 0 1049k 0 0:01:29 0:00:57 0:00:32 1331k 66 91.5M 66 60.4M 0 0 1055k 0 0:01:28 0:00:58 0:00:30 1312k 67 91.5M 67 61.8M 0 0 1061k 0 0:01:28 0:00:59 0:00:29 1356k 69 91.5M 69 63.2M 0 0 1066k 0 0:01:27 0:01:00 0:00:27 1382k 70 91.5M 70 64.5M 0 0 1072k 0 0:01:27 0:01:01 0:00:26 1395k 72 91.5M 72 66.0M 0 0 1078k 0 0:01:26 0:01:02 0:00:24 1411k 73 91.5M 73 67.4M 0 0 1085k 0 0:01:26 0:01:03 0:00:23 1430k 74 91.5M 74 68.6M 0 0 1087k 0 0:01:26 0:01:04 0:00:22 1395k 76 91.5M 76 69.9M 0 0 1090k 0 0:01:25 0:01:05 0:00:20 1379k 77 91.5M 77 71.3M 0 0 1096k 0 0:01:25 0:01:06 0:00:19 1388k 79 91.5M 79 72.8M 0 0 1101k 0 0:01:25 0:01:07 0:00:18 1394k 80 91.5M 80 74.0M 0 0 1104k 0 0:01:24 0:01:08 0:00:16 1353k 82 91.5M 82 75.2M 0 0 1106k 0 0:01:24 0:01:09 0:00:15 1356k 83 91.5M 83 76.5M 0 0 1109k 0 0:01:24 0:01:10 0:00:14 1356k 84 91.5M 84 77.5M 0 0 1107k 0 0:01:24 0:01:11 0:00:13 1257k 86 91.5M 86 78.8M 0 0 1110k 0 0:01:24 0:01:12 0:00:12 1225k 87 91.5M 87 79.8M 0 0 1109k 0 0:01:24 0:01:13 0:00:11 1184k 88 91.5M 88 80.9M 0 0 1110k 0 0:01:24 0:01:14 0:00:10 1161k 89 91.5M 89 82.0M 0 0 1110k 0 0:01:24 0:01:15 0:00:09 1126k 90 91.5M 90 83.1M 0 0 1111k 0 0:01:24 0:01:16 0:00:08 1160k 92 91.5M 92 84.3M 0 0 1111k 0 0:01:24 0:01:17 0:00:07 1126k 93 91.5M 93 85.4M 0 0 1112k 0 0:01:24 0:01:18 0:00:06 1142k 94 91.5M 94 86.6M 0 0 1113k 0 0:01:24 0:01:19 0:00:05 1157k 95 91.5M 95 87.8M 0 0 1115k 0 0:01:24 0:01:20 0:00:04 1185k 97 91.5M 97 89.2M 0 0 1118k 0 0:01:23 0:01:21 0:00:02 1238k 98 91.5M 98 90.2M 0 0 1118k 0 0:01:23 0:01:22 0:00:01 1225k 100 91.5M 100 91.5M 0 0 1122k 0 0:01:23 0:01:23 --:--:-- 1297k ==> artik: . ==> artik: . ==> artik: ARTIK IDE: DOWNLOADING ARTIK RUNTIME IMAGE ==> artik: . ==> artik: . ==> artik: Using default tag: latest ==> artik: latest: Pulling from codenvy/artik ==> artik: a3ed95caeb02: Already exists ==> artik: 236608c7b546: Already exists ==> artik: 8d035e21ff16: Already exists ==> artik: Digest: sha256:f25bd2a453391163c9f297d1f6578ed5ff19d4837dcf3a3a4c2d18014d386125 ==> artik: Status: Image is up to date for codenvy/artik:latest ==> artik: . ==> artik: . ==> artik: ARTIK IDE: PREPPING SERVER ==> artik: . ==> artik: . ==> artik: Launching a Docker registry for workspace snapshots. ==> artik: Found a registry container named registry. Attempting restart. ==> artik: Successful restart of registry container. ==> artik: Tomcat started. ==> artik: Running provisioner: shell... artik: Running: inline script ==> artik: . ==> artik: . ==> artik: ARTIK IDE: SERVER BOOTING ~10s ==> artik: AVAILABLE: http://192.168.28.28:8080 ==> artik: . ==> artik: .

What am I doing wrong? Can I get access to the VM directly since it seems to be a network type issue.

ghost commented 8 years ago

You aren't doing anything wrong. We need to reconsider the Vagrantfile.

Question. After vagrant suspend, do you reboot the machine? It works for me within one session. But not after a reboot

TylerJewell commented 8 years ago

@ShonkyCH So the sequence that I used when writing the Vagrantfile was to follow:

  1. Vagrant up
  2. Vagrant suspend
  3. Vagrant up

If you do vagrant provision, it will rerun the entire setup provisioner, which re-downloads the script. When I run the sequence above, the provisioner is not rerun. I am able to repeatedly perform the sequence above without error. So there seems to be some disconnect between what you are seeing and what I am.

You can get access to the VM by logging in with ssh using the "vagrant" user name.

HDC67 commented 8 years ago

Right. I'm saying I have to do a provision to make it work - not that up is doing the provision. However I would note that the vagrant help says to use vagrant resume rather than vagrant up to resume as up provisions. That said, it does seem to detect that which you can see in the vagrant output above.

provision       provisions the vagrant machine
resume          resume a suspended vagrant machine
suspend         suspends the machine
up              starts and provisions the vagrant environment

I think I have worked it out. If the VM is shutdown rather than suspended, it will not boot correctly which I think is what @eivantsov is saying too. Would also happen if the VM or host crashes since it would have to reboot.

So suspend does appear to be working actually (I wasn't). Initially I was sending ACPI shutdown messages from virtualbox which appear to shut it down properly. i.e. each time was a fresh boot.

Now I know how to log in, I can clearly see that there is nothing listening on port 8080 after a reboot, hence it doesn't work. There are a number of other ports not open that are open in a working VM so it appears the whole process is not being started properly at boot time. Something to be fixed for sure.

After a reboot:

Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN
tcp        0      0 127.0.0.1:25            0.0.0.0:*               LISTEN
tcp        0     64 192.168.28.28:22        192.168.28.1:56270      ESTABLISHED
tcp6       0      0 :::5000                 :::*                    LISTEN
tcp6       0      0 :::22                   :::*                    LISTEN
tcp6       0      0 ::1:25                  :::*                    LISTEN
udp        0      0 0.0.0.0:68              0.0.0.0:*
udp        0      0 0.0.0.0:18324           0.0.0.0:*
udp6       0      0 :::63478                :::*
raw6       0      0 :::58                   :::*                    7

After a provision:

Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN
tcp        0      0 127.0.0.1:25            0.0.0.0:*               LISTEN
tcp        0     64 192.168.28.28:22        192.168.28.1:55971      ESTABLISHED
tcp6       0      0 :::32001                :::*                    LISTEN
tcp6       0      0 127.0.0.1:8005          :::*                    LISTEN
tcp6       0      0 :::32101                :::*                    LISTEN
tcp6       0      0 :::5000                 :::*                    LISTEN
tcp6       0      0 :::8080                 :::*                    LISTEN
tcp6       0      0 :::22                   :::*                    LISTEN
tcp6       0      0 :::46777                :::*                    LISTEN
tcp6       0      0 ::1:25                  :::*                    LISTEN
udp        0      0 0.0.0.0:68              0.0.0.0:*
udp        0      0 0.0.0.0:1419            0.0.0.0:*
udp6       0      0 :::8346                 :::*
raw6       0      0 :::58                   :::*                    7
TylerJewell commented 8 years ago

@ShonkyCH @eivantsov -- I was able to confirm the issue. If the Vagrant VM is not properly suspended and then the computer is shut down and repowered, then the vagrant image does not properly reactivate itself. I have updated the Vagrantfile with a series of fixes to correct this.

We have a mandatory provisioner that always runs - whether it's vagrant up or vagrant resume. In that provisioner, we now check to see if the server is alive. If for some reason the server is not running, we'll restart it.

https://github.com/codenvy/artik-ide/pull/46

HDC67 commented 8 years ago

Yep. That's it. A fresh boot even if powered down properly, doesn't work.

We posted almost at exactly the same time :)

TylerJewell commented 8 years ago

Took me most of the day to chase it down and figure out a way to fix it. But glad we caught this. Thanks for reporting it.

TylerJewell commented 8 years ago

And made matching pull request for the Che core repository. https://github.com/eclipse/che/pull/1221

ghost commented 8 years ago

@ShonkyCH @TylerJewell this worked for me

ghost commented 8 years ago

@ShonkyCH the pull request has been merged. Can you give it another shot?

HDC67 commented 8 years ago

Well it seems to have work although the messages are a bit strange. The VM was shutdown. I replaced the VagrantFile with the new one and did a vagrant up :

Bringing machine 'artik' up with 'virtualbox' provider...
==> artik: Clearing any previously set forwarded ports...
==> artik: Clearing any previously set network interfaces...
==> artik: Preparing network interfaces based on configuration...
    artik: Adapter 1: nat
    artik: Adapter 2: hostonly
==> artik: Forwarding ports...
    artik: 22 (guest) => 2222 (host) (adapter 1)
==> artik: Running 'pre-boot' VM customizations...
==> artik: Booting VM...
==> artik: Waiting for machine to boot. This may take a few minutes...
    artik: SSH address: 127.0.0.1:2222
    artik: SSH username: vagrant
    artik: SSH auth method: private key
    artik: Warning: Remote connection disconnect. Retrying...
    artik: Warning: Remote connection disconnect. Retrying...
    artik: Warning: Remote connection disconnect. Retrying...
==> artik: Machine booted and ready!
==> artik: Checking for guest additions in VM...
==> artik: Configuring and enabling network interfaces...
==> artik: Mounting shared folders...
    artik: /home/vagrant/.che => C:/Users/<user>/Downloads/CHE
==> artik: Machine already provisioned. Run `vagrant provision` or use the `--provision`
==> artik: flag to force provisioning. Provisioners marked to run always will still run.
==> artik: Running provisioner: shell...
    artik: Running: inline script
==> artik: ---------------------------------------------
==> artik: .
==> artik: ARTIK IDE: SERVER NOT RESPONSIVE -- REBOOTING
==> artik: .
==> artik: ---------------------------------------------
==> artik: --------------------------------------
==> artik: .
==> artik: ARTIK IDE: SERVER BOOTED AND REACHABLE
==> artik: AVAILABLE: http://192.168.28.28:8080
==> artik: .
==> artik: --------------------------------------

It paused for a while at "Running: inline script" then gave the message about rebooting. It didn't reboot though - I had the console for the VM open. However it did start respond on the webserver after all that. So not sure that it's supposed to do that but the end result seems ok.

TylerJewell commented 8 years ago

Hmmm... Well inside, it is actually restarting the ARTIK IDE server. Maybe rebooting isn't the best syntax. I think restarting would be a better text to use.

HDC67 commented 8 years ago

Ah OK. I assumed it was the whole VM. It's a docker VM right?

Should it be unresponsive every time though? It seems to always do it (3 out of 3 times so far).

TylerJewell commented 8 years ago

Not sure I follow? The VM itself should be mostly silent while it goes through the internal cycle of restarting the ARTIK IDE server. Once the IDE server is active, the vagrant up command should return on the console. It checks every 5 seconds to see if the server is up and then returns once it verifies the server is running.

HDC67 commented 8 years ago

Every time I boot the whole VM, it says (what I assume) is the docker VM is unresponsive and it reboots it. Surely at a first boot it should just work first time?

TylerJewell commented 8 years ago

The initial threshold for triggering a restart is 60 seconds in the Vagrantfile in master. It usually never takes more than 10 seconds for mine to boot, but maybe your computer is a bit slower. Could you modify the line:

      # If we are not awake after 60 seconds, restart server
      if [ $counter == "11" ]; then

Change this to a number that is much larger. Does the issue still happen where the restart is triggered?

HDC67 commented 8 years ago

It's certainly not the latest but it's no slouch either. Runs eveything I throw at it. Dual core i7-2640M, 16GB RAM, brand new Sandisk Ultra II SSD, brand new clean Windows 10 installation.

Changed the number to 110 and it just sat at the running inline script stage for a longer time, eventually failed and the IDE is not functional at all now.

....
==> artik: Machine already provisioned. Run `vagrant provision` or use the `--provision`
==> artik: flag to force provisioning. Provisioners marked to run always will still run.
==> artik: Running provisioner: shell...
    artik: Running: inline script
==> artik: -------------------------------------------
==> artik: .
==> artik: ARTIK IDE: SERVER NOT RESPONSIVE -- EXITING
==> artik:            CONTACT SUPPORT FOR ASSISTANCE
==> artik: .
==> artik: -------------------------------------------
TylerJewell commented 8 years ago

Ok - so if you do a vagrant destroy followed by a vagrant up, you experience the same issues? I am wondering if your Virtualbox networking settings aren't part of the issue. We have seen NDIS driver issues from time to time.

HDC67 commented 8 years ago

What you suggested won't work looking at that vagrantfile. It will bail out as soon as the counter hits 35 unless I change that value too. 35 is about 3 minutes and it should definitely have booted by then.

Remember this all worked fine every time with a vagrant provision and worked with the "reboot" too as long as it started it again. It didn't work when I changed the timeout because the counter loop bailed out early. Is there potentially a race early on when the start is issued the first time? I doubt my VirtualBox is at fault honestly.

echo vagrant | sudo -S -E -u vagrant /home/vagrant/eclipse-che-*/bin/che.sh --remote:${IP} --skip:client -g start &>/dev/null

... seems to need to be run again.

HDC67 commented 8 years ago

I'm not sure I want to destroy it. It seemed to want to download the ~700MB file every time when I first set it up. The caching doesn't appear to work.

Edit: OK I destroyed and started again. It didn't redownload this time.

TylerJewell commented 8 years ago

You can SSH into the VM and then manually kill any java process. And then you can rerun the Che server launch manually using the syntax in the line above.

/home/vagrant/eclipse-che-*/bin/che.sh --remote:${IP} run

Replace IP with the IP address of the VM.

HDC67 commented 8 years ago

Nope. Same problem after destroying and recreating the whole thing. I can see there is no java process to kill running at all - until after the Rebooting message where it attempts to start the whole thing again.

So that's why it's not working and no amount of time will fix that. It seems it's not starting it initially - maybe trying too early?

TylerJewell commented 8 years ago

That is super odd. It means that the server launch sequence is never being run. Is there any way we can do a screen share where I can investigate? I will not be free for an hour, though.

HDC67 commented 8 years ago

Not today. It's 12:20am here in Australia now so nearly time to knock off. Let me have a bit of look at the script.

I don't really follow what vagrant does exactly, but $script never seems to be executed after the first provision or if I force another one. $script2 only executes the che.sh start after the 60 second timeout. So how else does this start i.e. run the che.sh script? $script only runs for a provision right? If I'm right I can't see how this can possibly start automatically unless within the CentOS VM somehow che.sh starts on its own.

I'm not sure if the VM boot log helps you at all. I do see a bit of docker stuff going on with NetworkManager.

14:23:30 was about when I started vagrant up. 14:24:06 is where I logged in and could see no java process 14:24:14 is the beginning of $script2 14:25:10 is the point where the script says it's "rebooting"

I'm out for the night now.

Boot log

May 12 14:23:56 localhost rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="594" x-info="http://www.rsyslog.com"] start
May 12 14:23:50 localhost journal: Runtime journal is using 8.0M (max 189.5M, leaving 284.3M of free 1.8G, current limit 189.5M).
May 12 14:23:50 localhost kernel: Initializing cgroup subsys cpuset
May 12 14:23:50 localhost kernel: Initializing cgroup subsys cpu
May 12 14:23:50 localhost kernel: Initializing cgroup subsys cpuacct
May 12 14:23:50 localhost kernel: Linux version 3.10.0-229.el7.x86_64 (builder@kbuilder.dev.centos.org) (gcc version 4.8.2 20140120 (Red Hat 4.8.2-16) (GCC) ) #1 SMP Fri Mar 6 11:36:42 UTC 2015
May 12 14:23:50 localhost kernel: Command line: BOOT_IMAGE=/vmlinuz-3.10.0-229.el7.x86_64 root=/dev/mapper/centos-root ro rd.lvm.lv=centos/root rd.lvm.lv=centos/swap crashkernel=auto rhgb quiet LANG=en_US.UTF-8
May 12 14:23:50 localhost kernel: e820: BIOS-provided physical RAM map:
May 12 14:23:50 localhost kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
May 12 14:23:50 localhost kernel: BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
May 12 14:23:50 localhost kernel: BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
May 12 14:23:50 localhost kernel: BIOS-e820: [mem 0x0000000000100000-0x00000000dffeffff] usable
May 12 14:23:50 localhost kernel: BIOS-e820: [mem 0x00000000dfff0000-0x00000000dfffffff] ACPI data
May 12 14:23:50 localhost kernel: BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
May 12 14:23:50 localhost kernel: BIOS-e820: [mem 0x0000000100000000-0x000000011fffffff] usable
May 12 14:23:50 localhost kernel: NX (Execute Disable) protection: active
May 12 14:23:50 localhost kernel: SMBIOS 2.5 present.
May 12 14:23:50 localhost kernel: Hypervisor detected: KVM
May 12 14:23:50 localhost kernel: No AGP bridge found
May 12 14:23:50 localhost kernel: e820: last_pfn = 0x120000 max_arch_pfn = 0x400000000
May 12 14:23:50 localhost kernel: x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
May 12 14:23:50 localhost kernel: CPU MTRRs all blank - virtualized system.
May 12 14:23:50 localhost kernel: e820: last_pfn = 0xdfff0 max_arch_pfn = 0x400000000
May 12 14:23:50 localhost kernel: found SMP MP-table at [mem 0x0009fff0-0x0009ffff] mapped at [ffff88000009fff0]
May 12 14:23:50 localhost kernel: init_memory_mapping: [mem 0x00000000-0x000fffff]
May 12 14:23:50 localhost kernel: init_memory_mapping: [mem 0x11fe00000-0x11fffffff]
May 12 14:23:50 localhost kernel: init_memory_mapping: [mem 0x11c000000-0x11fdfffff]
May 12 14:23:50 localhost kernel: init_memory_mapping: [mem 0x100000000-0x11bffffff]
May 12 14:23:50 localhost kernel: init_memory_mapping: [mem 0x00100000-0xdffeffff]
May 12 14:23:50 localhost kernel: RAMDISK: [mem 0x35e2f000-0x36f0ffff]
May 12 14:23:50 localhost kernel: ACPI: RSDP 00000000000e0000 00024 (v02 VBOX  )
May 12 14:23:50 localhost kernel: ACPI: XSDT 00000000dfff0030 0003C (v01 VBOX   VBOXXSDT 00000001 ASL  00000061)
May 12 14:23:50 localhost kernel: ACPI: FACP 00000000dfff00f0 000F4 (v04 VBOX   VBOXFACP 00000001 ASL  00000061)
May 12 14:23:50 localhost kernel: ACPI: DSDT 00000000dfff0470 02106 (v01 VBOX   VBOXBIOS 00000002 INTL 20100528)
May 12 14:23:50 localhost kernel: ACPI: FACS 00000000dfff0200 00040
May 12 14:23:50 localhost kernel: ACPI: APIC 00000000dfff0240 00054 (v02 VBOX   VBOXAPIC 00000001 ASL  00000061)
May 12 14:23:50 localhost kernel: ACPI: SSDT 00000000dfff02a0 001CC (v01 VBOX   VBOXCPUT 00000002 INTL 20100528)
May 12 14:23:50 localhost kernel: No NUMA configuration found
May 12 14:23:50 localhost kernel: Faking a node at [mem 0x0000000000000000-0x000000011fffffff]
May 12 14:23:50 localhost kernel: Initmem setup node 0 [mem 0x00000000-0x11fffffff]
May 12 14:23:50 localhost kernel:  NODE_DATA [mem 0x11ffd5000-0x11fffbfff]
May 12 14:23:50 localhost kernel: Reserving 161MB of memory at 688MB for crashkernel (System RAM: 4095MB)
May 12 14:23:50 localhost kernel: kvm-clock: Using msrs 4b564d01 and 4b564d00
May 12 14:23:50 localhost kernel: kvm-clock: cpu 0, msr 1:1ff85001, primary cpu clock
May 12 14:23:50 localhost kernel: Zone ranges:
May 12 14:23:50 localhost kernel:  DMA      [mem 0x00001000-0x00ffffff]
May 12 14:23:50 localhost kernel:  DMA32    [mem 0x01000000-0xffffffff]
May 12 14:23:50 localhost kernel:  Normal   [mem 0x100000000-0x11fffffff]
May 12 14:23:50 localhost kernel: Movable zone start for each node
May 12 14:23:50 localhost kernel: Early memory node ranges
May 12 14:23:50 localhost kernel:  node   0: [mem 0x00001000-0x0009efff]
May 12 14:23:50 localhost kernel:  node   0: [mem 0x00100000-0xdffeffff]
May 12 14:23:50 localhost kernel:  node   0: [mem 0x100000000-0x11fffffff]
May 12 14:23:50 localhost kernel: ACPI: PM-Timer IO Port: 0x4008
May 12 14:23:50 localhost kernel: ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
May 12 14:23:50 localhost kernel: ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0])
May 12 14:23:50 localhost kernel: IOAPIC[0]: apic_id 1, version 17, address 0xfec00000, GSI 0-23
May 12 14:23:50 localhost kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
May 12 14:23:50 localhost kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
May 12 14:23:50 localhost kernel: Using ACPI (MADT) for SMP configuration information
May 12 14:23:50 localhost kernel: smpboot: Allowing 1 CPUs, 0 hotplug CPUs
May 12 14:23:50 localhost kernel: PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
May 12 14:23:50 localhost kernel: PM: Registered nosave memory: [mem 0x000a0000-0x000effff]
May 12 14:23:50 localhost kernel: PM: Registered nosave memory: [mem 0x000f0000-0x000fffff]
May 12 14:23:50 localhost kernel: PM: Registered nosave memory: [mem 0xdfff0000-0xdfffffff]
May 12 14:23:50 localhost kernel: PM: Registered nosave memory: [mem 0xe0000000-0xfffbffff]
May 12 14:23:50 localhost kernel: PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff]
May 12 14:23:50 localhost kernel: e820: [mem 0xe0000000-0xfffbffff] available for PCI devices
May 12 14:23:50 localhost kernel: Booting paravirtualized kernel on KVM
May 12 14:23:50 localhost kernel: setup_percpu: NR_CPUS:5120 nr_cpumask_bits:1 nr_cpu_ids:1 nr_node_ids:1
May 12 14:23:50 localhost kernel: PERCPU: Embedded 28 pages/cpu @ffff88011fc00000 s82752 r8192 d23744 u2097152
May 12 14:23:50 localhost kernel: Built 1 zonelists in Node order, mobility grouping on.  Total pages: 1032057
May 12 14:23:50 localhost kernel: Policy zone: Normal
May 12 14:23:50 localhost kernel: Kernel command line: BOOT_IMAGE=/vmlinuz-3.10.0-229.el7.x86_64 root=/dev/mapper/centos-root ro rd.lvm.lv=centos/root rd.lvm.lv=centos/swap crashkernel=auto rhgb quiet LANG=en_US.UTF-8
May 12 14:23:50 localhost kernel: PID hash table entries: 4096 (order: 3, 32768 bytes)
May 12 14:23:50 localhost kernel: xsave: enabled xstate_bv 0x7, cntxt size 0x340
May 12 14:23:50 localhost kernel: Checking aperture...
May 12 14:23:50 localhost kernel: No AGP bridge found
May 12 14:23:50 localhost kernel: Memory: 3863896k/4718592k available (6244k kernel code, 524744k absent, 329952k reserved, 4178k data, 1604k init)
May 12 14:23:50 localhost kernel: SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
May 12 14:23:50 localhost kernel: Hierarchical RCU implementation.
May 12 14:23:50 localhost kernel:       RCU restricting CPUs from NR_CPUS=5120 to nr_cpu_ids=1.
May 12 14:23:50 localhost kernel:       Experimental no-CBs for all CPUs
May 12 14:23:50 localhost kernel:       Experimental no-CBs CPUs: 0.
May 12 14:23:50 localhost kernel: NR_IRQS:327936 nr_irqs:256 16
May 12 14:23:50 localhost kernel: Console: colour VGA+ 80x25
May 12 14:23:50 localhost kernel: console [tty0] enabled
May 12 14:23:50 localhost kernel: allocated 16777216 bytes of page_cgroup
May 12 14:23:50 localhost kernel: please try 'cgroup_disable=memory' option if you don't want memory cgroups
May 12 14:23:50 localhost kernel: tsc: Detected 2793.656 MHz processor
May 12 14:23:50 localhost kernel: Calibrating delay loop (skipped) preset value.. 5587.31 BogoMIPS (lpj=2793656)
May 12 14:23:50 localhost kernel: pid_max: default: 32768 minimum: 301
May 12 14:23:50 localhost kernel: Security Framework initialized
May 12 14:23:50 localhost kernel: SELinux:  Initializing.
May 12 14:23:50 localhost kernel: Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
May 12 14:23:50 localhost kernel: Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
May 12 14:23:50 localhost kernel: Mount-cache hash table entries: 4096
May 12 14:23:50 localhost kernel: Initializing cgroup subsys memory
May 12 14:23:50 localhost kernel: Initializing cgroup subsys devices
May 12 14:23:50 localhost kernel: Initializing cgroup subsys freezer
May 12 14:23:50 localhost kernel: Initializing cgroup subsys net_cls
May 12 14:23:50 localhost kernel: Initializing cgroup subsys blkio
May 12 14:23:50 localhost kernel: Initializing cgroup subsys perf_event
May 12 14:23:50 localhost kernel: Initializing cgroup subsys hugetlb
May 12 14:23:50 localhost kernel: CPU: Physical Processor ID: 0
May 12 14:23:50 localhost kernel: mce: CPU supports 0 MCE banks
May 12 14:23:50 localhost kernel: Last level iTLB entries: 4KB 512, 2MB 0, 4MB 0
Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32
tlb_flushall_shift: 6
May 12 14:23:50 localhost kernel: Freeing SMP alternatives: 24k freed
May 12 14:23:50 localhost kernel: ACPI: Core revision 20130517
May 12 14:23:50 localhost kernel: ACPI: All ACPI Tables successfully acquired
May 12 14:23:50 localhost kernel: ftrace: allocating 23909 entries in 94 pages
May 12 14:23:50 localhost kernel: ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
May 12 14:23:50 localhost kernel: smpboot: CPU0: Intel(R) Core(TM) i7-2640M CPU @ 2.80GHz (fam: 06, model: 2a, stepping: 07)
May 12 14:23:50 localhost kernel: APIC calibration not consistent with PM-Timer: 98ms instead of 100ms
May 12 14:23:50 localhost kernel: APIC delta adjusted to PM-Timer: 6286894 (6191736)
May 12 14:23:50 localhost kernel: Performance Events: unsupported p6 CPU model 42 no PMU driver, software events only.
May 12 14:23:50 localhost kernel: KVM setup paravirtual spinlock
May 12 14:23:50 localhost kernel: Brought up 1 CPUs
May 12 14:23:50 localhost kernel: smpboot: Total of 1 processors activated (5587.31 BogoMIPS)
May 12 14:23:50 localhost kernel: NMI watchdog: disabled (cpu0): hardware events not enabled
May 12 14:23:50 localhost kernel: devtmpfs: initialized
May 12 14:23:50 localhost kernel: EVM: security.selinux
May 12 14:23:50 localhost kernel: EVM: security.ima
May 12 14:23:50 localhost kernel: EVM: security.capability
May 12 14:23:50 localhost kernel: atomic64 test passed for x86-64 platform with CX8 and with SSE
May 12 14:23:50 localhost kernel: NET: Registered protocol family 16
May 12 14:23:50 localhost kernel: ACPI: bus type PCI registered
May 12 14:23:50 localhost kernel: acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
May 12 14:23:50 localhost kernel: PCI: Using configuration type 1 for base access
May 12 14:23:50 localhost kernel: ACPI: Added _OSI(Module Device)
May 12 14:23:50 localhost kernel: ACPI: Added _OSI(Processor Device)
May 12 14:23:50 localhost kernel: ACPI: Added _OSI(3.0 _SCP Extensions)
May 12 14:23:50 localhost kernel: ACPI: Added _OSI(Processor Aggregator Device)
May 12 14:23:50 localhost kernel: ACPI: Executed 1 blocks of module-level executable AML code
May 12 14:23:50 localhost kernel: ACPI: Interpreter enabled
May 12 14:23:50 localhost kernel: ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S1_] (20130517/hwxface-571)
May 12 14:23:50 localhost kernel: ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S2_] (20130517/hwxface-571)
May 12 14:23:50 localhost kernel: ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S3_] (20130517/hwxface-571)
May 12 14:23:50 localhost kernel: ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S4_] (20130517/hwxface-571)
May 12 14:23:50 localhost kernel: ACPI: (supports S0 S5)
May 12 14:23:50 localhost kernel: ACPI: Using IOAPIC for interrupt routing
May 12 14:23:50 localhost kernel: PCI: Ignoring host bridge windows from ACPI; if necessary, use "pci=use_crs" and report a bug
May 12 14:23:50 localhost kernel: ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
May 12 14:23:50 localhost kernel: acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
May 12 14:23:50 localhost kernel: acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
May 12 14:23:50 localhost kernel: acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
May 12 14:23:50 localhost kernel: PCI host bridge to bus 0000:00
May 12 14:23:50 localhost kernel: pci_bus 0000:00: root bus resource [bus 00-ff]
May 12 14:23:50 localhost kernel: pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
May 12 14:23:50 localhost kernel: pci_bus 0000:00: root bus resource [mem 0x00000000-0xfffffffff]
May 12 14:23:50 localhost kernel: pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
May 12 14:23:50 localhost kernel: pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
May 12 14:23:50 localhost kernel: pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
May 12 14:23:50 localhost kernel: pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
May 12 14:23:50 localhost kernel: ACPI: PCI Interrupt Link [LNKA] (IRQs 5 9 10 *11)
May 12 14:23:50 localhost kernel: ACPI: PCI Interrupt Link [LNKB] (IRQs 5 9 10 *11)
May 12 14:23:50 localhost kernel: ACPI: PCI Interrupt Link [LNKC] (IRQs 5 9 *10 11)
May 12 14:23:50 localhost kernel: ACPI: PCI Interrupt Link [LNKD] (IRQs 5 *9 10 11)
May 12 14:23:50 localhost kernel: ACPI: Enabled 2 GPEs in block 00 to 07
May 12 14:23:50 localhost kernel: vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
May 12 14:23:50 localhost kernel: vgaarb: loaded
May 12 14:23:50 localhost kernel: vgaarb: bridge control possible 0000:00:02.0
May 12 14:23:50 localhost kernel: SCSI subsystem initialized
May 12 14:23:50 localhost kernel: ACPI: bus type USB registered
May 12 14:23:50 localhost kernel: usbcore: registered new interface driver usbfs
May 12 14:23:50 localhost kernel: usbcore: registered new interface driver hub
May 12 14:23:50 localhost kernel: usbcore: registered new device driver usb
May 12 14:23:50 localhost kernel: PCI: Using ACPI for IRQ routing
May 12 14:23:50 localhost kernel: NetLabel: Initializing
May 12 14:23:50 localhost kernel: NetLabel:  domain hash size = 128
May 12 14:23:50 localhost kernel: NetLabel:  protocols = UNLABELED CIPSOv4
May 12 14:23:50 localhost kernel: NetLabel:  unlabeled traffic allowed by default
May 12 14:23:50 localhost kernel: Switching to clocksource kvm-clock
May 12 14:23:50 localhost kernel: pnp: PnP ACPI init
May 12 14:23:50 localhost kernel: ACPI: bus type PNP registered
May 12 14:23:50 localhost kernel: pnp: PnP ACPI: found 3 devices
May 12 14:23:50 localhost kernel: ACPI: bus type PNP unregistered
May 12 14:23:50 localhost kernel: NET: Registered protocol family 2
May 12 14:23:50 localhost kernel: TCP established hash table entries: 32768 (order: 6, 262144 bytes)
May 12 14:23:50 localhost kernel: TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
May 12 14:23:50 localhost kernel: TCP: Hash tables configured (established 32768 bind 32768)
May 12 14:23:50 localhost kernel: TCP: reno registered
May 12 14:23:50 localhost kernel: UDP hash table entries: 2048 (order: 4, 65536 bytes)
May 12 14:23:50 localhost kernel: UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
May 12 14:23:50 localhost kernel: NET: Registered protocol family 1
May 12 14:23:50 localhost kernel: pci 0000:00:00.0: Limiting direct PCI/PCI transfers
May 12 14:23:50 localhost kernel: pci 0000:00:01.0: Activating ISA DMA hang workarounds
May 12 14:23:50 localhost kernel: Unpacking initramfs...
May 12 14:23:50 localhost kernel: Freeing initrd memory: 17284k freed
May 12 14:23:50 localhost kernel: PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
May 12 14:23:50 localhost kernel: software IO TLB [mem 0xdbff0000-0xdfff0000] (64MB) mapped at [ffff8800dbff0000-ffff8800dffeffff]
May 12 14:23:50 localhost kernel: platform rtc_cmos: registered platform RTC device (no PNP device found)
May 12 14:23:50 localhost kernel: RAPL PMU detected, hw unit 2^-0 Joules, API unit is 2^-32 Joules, 3 fixed counters 10737418240 ms ovfl timer
May 12 14:23:50 localhost kernel: microcode: CPU0 sig=0x206a7, pf=0x10, revision=0x0
May 12 14:23:50 localhost kernel: microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
May 12 14:23:50 localhost kernel: futex hash table entries: 256 (order: 2, 16384 bytes)
May 12 14:23:50 localhost kernel: Initialise system trusted keyring
May 12 14:23:50 localhost kernel: audit: initializing netlink socket (disabled)
May 12 14:23:50 localhost kernel: type=2000 audit(1463063041.372:1): initialized
May 12 14:23:50 localhost kernel: HugeTLB registered 2 MB page size, pre-allocated 0 pages
May 12 14:23:50 localhost kernel: zbud: loaded
May 12 14:23:50 localhost kernel: VFS: Disk quotas dquot_6.5.2
May 12 14:23:50 localhost kernel: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
May 12 14:23:50 localhost kernel: msgmni has been set to 7580
May 12 14:23:50 localhost kernel: Key type big_key registered
May 12 14:23:50 localhost kernel: alg: No test for stdrng (krng)
May 12 14:23:50 localhost kernel: NET: Registered protocol family 38
May 12 14:23:50 localhost kernel: Key type asymmetric registered
May 12 14:23:50 localhost kernel: Asymmetric key parser 'x509' registered
May 12 14:23:50 localhost kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
May 12 14:23:50 localhost kernel: io scheduler noop registered
May 12 14:23:50 localhost kernel: io scheduler deadline registered (default)
May 12 14:23:50 localhost kernel: io scheduler cfq registered
May 12 14:23:50 localhost kernel: pci_hotplug: PCI Hot Plug PCI Core version: 0.5
May 12 14:23:50 localhost kernel: pciehp: PCI Express Hot Plug Controller Driver version: 0.4
May 12 14:23:50 localhost kernel: ACPI: AC Adapter [AC] (on-line)
May 12 14:23:50 localhost kernel: input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
May 12 14:23:50 localhost kernel: ACPI: Power Button [PWRF]
May 12 14:23:50 localhost kernel: input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input1
May 12 14:23:50 localhost kernel: ACPI: Sleep Button [SLPF]
May 12 14:23:50 localhost kernel: GHES: HEST is not enabled!
May 12 14:23:50 localhost kernel: Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
May 12 14:23:50 localhost kernel: Non-volatile memory driver v1.3
May 12 14:23:50 localhost kernel: Linux agpgart interface v0.103
May 12 14:23:50 localhost kernel: crash memory driver: version 1.1
May 12 14:23:50 localhost kernel: rdac: device handler registered
May 12 14:23:50 localhost kernel: ACPI: Battery Slot [BAT0] (battery present)
May 12 14:23:50 localhost kernel: hp_sw: device handler registered
May 12 14:23:50 localhost kernel: emc: device handler registered
May 12 14:23:50 localhost kernel: alua: device handler registered
May 12 14:23:50 localhost kernel: libphy: Fixed MDIO Bus: probed
May 12 14:23:50 localhost kernel: ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
May 12 14:23:50 localhost kernel: ehci-pci: EHCI PCI platform driver
May 12 14:23:50 localhost kernel: ehci-pci 0000:00:0b.0: EHCI Host Controller
May 12 14:23:50 localhost kernel: ehci-pci 0000:00:0b.0: new USB bus registered, assigned bus number 1
May 12 14:23:50 localhost kernel: ehci-pci 0000:00:0b.0: irq 19, io mem 0xf0840000
May 12 14:23:50 localhost kernel: ehci-pci 0000:00:0b.0: USB 2.0 started, EHCI 1.00
May 12 14:23:50 localhost kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
May 12 14:23:50 localhost kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
May 12 14:23:50 localhost kernel: usb usb1: Product: EHCI Host Controller
May 12 14:23:50 localhost kernel: usb usb1: Manufacturer: Linux 3.10.0-229.el7.x86_64 ehci_hcd
May 12 14:23:50 localhost kernel: usb usb1: SerialNumber: 0000:00:0b.0
May 12 14:23:50 localhost kernel: hub 1-0:1.0: USB hub found
May 12 14:23:50 localhost kernel: hub 1-0:1.0: 12 ports detected
May 12 14:23:50 localhost kernel: ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
May 12 14:23:50 localhost kernel: ohci-pci: OHCI PCI platform driver
May 12 14:23:50 localhost kernel: ohci-pci 0000:00:06.0: OHCI PCI host controller
May 12 14:23:50 localhost kernel: ohci-pci 0000:00:06.0: new USB bus registered, assigned bus number 2
May 12 14:23:50 localhost kernel: ohci-pci 0000:00:06.0: irq 22, io mem 0xf0804000
May 12 14:23:50 localhost kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
May 12 14:23:50 localhost kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
May 12 14:23:50 localhost kernel: usb usb2: Product: OHCI PCI host controller
May 12 14:23:50 localhost kernel: usb usb2: Manufacturer: Linux 3.10.0-229.el7.x86_64 ohci_hcd
May 12 14:23:50 localhost kernel: usb usb2: SerialNumber: 0000:00:06.0
May 12 14:23:50 localhost kernel: hub 2-0:1.0: USB hub found
May 12 14:23:50 localhost kernel: hub 2-0:1.0: 12 ports detected
May 12 14:23:50 localhost kernel: uhci_hcd: USB Universal Host Controller Interface driver
May 12 14:23:50 localhost kernel: usbcore: registered new interface driver usbserial
May 12 14:23:50 localhost kernel: usbcore: registered new interface driver usbserial_generic
May 12 14:23:50 localhost kernel: usbserial: USB Serial support registered for generic
May 12 14:23:50 localhost kernel: i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at 0x60,0x64 irq 1,12
May 12 14:23:50 localhost kernel: serio: i8042 KBD port at 0x60,0x64 irq 1
May 12 14:23:50 localhost kernel: serio: i8042 AUX port at 0x60,0x64 irq 12
May 12 14:23:50 localhost kernel: mousedev: PS/2 mouse device common for all mice
May 12 14:23:50 localhost kernel: rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
May 12 14:23:50 localhost kernel: rtc_cmos rtc_cmos: alarms up to one day, 114 bytes nvram
May 12 14:23:50 localhost kernel: cpuidle: using governor menu
May 12 14:23:50 localhost kernel: hidraw: raw HID events driver (C) Jiri Kosina
May 12 14:23:50 localhost kernel: usbcore: registered new interface driver usbhid
May 12 14:23:50 localhost kernel: usbhid: USB HID core driver
May 12 14:23:50 localhost kernel: drop_monitor: Initializing network drop monitor service
May 12 14:23:50 localhost kernel: TCP: cubic registered
May 12 14:23:50 localhost kernel: Initializing XFRM netlink socket
May 12 14:23:50 localhost kernel: NET: Registered protocol family 10
May 12 14:23:50 localhost kernel: NET: Registered protocol family 17
May 12 14:23:50 localhost kernel: Loading compiled-in X.509 certificates
May 12 14:23:50 localhost kernel: Loaded X.509 cert 'CentOS Linux kpatch signing key: ea0413152cde1d98ebdca3fe6f0230904c9ef717'
May 12 14:23:50 localhost kernel: Loaded X.509 cert 'CentOS Linux Driver update signing key: 7f421ee0ab69461574bb358861dbe77762a4201b'
May 12 14:23:50 localhost kernel: Loaded X.509 cert 'CentOS Linux kernel signing key: a62a0e1d6a6e484e9bfd7368af34081048e535e5'
May 12 14:23:50 localhost kernel: registered taskstats version 1
May 12 14:23:50 localhost kernel: input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input2
May 12 14:23:50 localhost kernel: Key type trusted registered
May 12 14:23:50 localhost kernel: Key type encrypted registered
May 12 14:23:50 localhost kernel: IMA: No TPM chip found, activating TPM-bypass!
May 12 14:23:50 localhost kernel: rtc_cmos rtc_cmos: setting system clock to 2016-05-12 14:23:50 UTC (1463063030)
May 12 14:23:50 localhost kernel: Freeing unused kernel memory: 1604k freed
May 12 14:23:50 localhost systemd[1]: systemd 208 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ)
May 12 14:23:50 localhost systemd[1]: Detected virtualization 'kvm'.
May 12 14:23:50 localhost systemd[1]: Running in initial RAM disk.
May 12 14:23:50 localhost systemd[1]: Set hostname to <localhost.localdomain>.
May 12 14:23:50 localhost systemd[1]: Expecting device dev-mapper-centos\x2droot.device...
May 12 14:23:50 localhost systemd[1]: Starting -.slice.
May 12 14:23:50 localhost systemd[1]: Created slice -.slice.
May 12 14:23:50 localhost systemd[1]: Starting System Slice.
May 12 14:23:50 localhost systemd[1]: Created slice System Slice.
May 12 14:23:50 localhost systemd[1]: Starting Slices.
May 12 14:23:50 localhost systemd[1]: Reached target Slices.
May 12 14:23:50 localhost systemd[1]: Starting Timers.
May 12 14:23:50 localhost systemd[1]: Reached target Timers.
May 12 14:23:50 localhost systemd[1]: Starting Journal Socket.
May 12 14:23:50 localhost systemd[1]: Listening on Journal Socket.
May 12 14:23:50 localhost systemd[1]: Started dracut ask for additional cmdline parameters.
May 12 14:23:50 localhost systemd[1]: Starting dracut cmdline hook...
May 12 14:23:50 localhost systemd[1]: Started Load Kernel Modules.
May 12 14:23:50 localhost systemd[1]: Starting Setup Virtual Console...
May 12 14:23:50 localhost systemd[1]: Starting Journal Service...
May 12 14:23:50 localhost systemd[1]: Started Journal Service.
May 12 14:23:50 localhost kernel: psmouse serio1: alps: Unknown ALPS touchpad: E7=10 00 64, EC=10 00 64
May 12 14:23:50 localhost journal: Journal started
May 12 14:23:50 localhost systemd: Starting udev Kernel Socket.
May 12 14:23:50 localhost systemd: Listening on udev Kernel Socket.
May 12 14:23:50 localhost systemd: Starting udev Control Socket.
May 12 14:23:50 localhost systemd: Listening on udev Control Socket.
May 12 14:23:50 localhost systemd: Starting Sockets.
May 12 14:23:50 localhost systemd: Reached target Sockets.
May 12 14:23:50 localhost systemd: Starting Create list of required static device nodes for the current kernel...
May 12 14:23:50 localhost systemd: Starting Apply Kernel Variables...
May 12 14:23:50 localhost systemd: Starting Swap.
May 12 14:23:50 localhost systemd: Reached target Swap.
May 12 14:23:50 localhost systemd: Starting Local File Systems.
May 12 14:23:50 localhost systemd: Reached target Local File Systems.
May 12 14:23:50 localhost systemd: Started Apply Kernel Variables.
May 12 14:23:50 localhost systemd: Started Create list of required static device nodes for the current kernel.
May 12 14:23:50 localhost systemd: Starting Create static device nodes in /dev...
May 12 14:23:50 localhost systemd: Started Create static device nodes in /dev.
May 12 14:23:50 localhost kernel: input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input3
May 12 14:23:50 localhost dracut-cmdline: dracut-7 (Core) dracut-033-240.el7
May 12 14:23:50 localhost dracut-cmdline: Using kernel command line parameters:
May 12 14:23:50 localhost systemd: Started Setup Virtual Console.
May 12 14:23:50 localhost systemd: Started dracut cmdline hook.
May 12 14:23:50 localhost systemd: Starting dracut pre-udev hook...
May 12 14:23:50 localhost kernel: device-mapper: uevent: version 1.0.3
May 12 14:23:50 localhost kernel: device-mapper: ioctl: 4.29.0-ioctl (2014-10-28) initialised: dm-devel@redhat.com
May 12 14:23:50 localhost systemd: Started dracut pre-udev hook.
May 12 14:23:50 localhost systemd: Starting udev Kernel Device Manager...
May 12 14:23:50 localhost systemd: Started udev Kernel Device Manager.
May 12 14:23:50 localhost systemd: Started dracut pre-trigger hook.
May 12 14:23:50 localhost systemd: Starting udev Coldplug all Devices...
May 12 14:23:50 localhost systemd-udevd[228]: starting version 208
May 12 14:23:50 localhost systemd: Mounting Configuration File System...
May 12 14:23:50 localhost systemd: Mounted Configuration File System.
May 12 14:23:51 localhost systemd: Started udev Coldplug all Devices.
May 12 14:23:51 localhost systemd: Starting dracut initqueue hook...
May 12 14:23:51 localhost systemd: Starting System Initialization.
May 12 14:23:51 localhost systemd: Reached target System Initialization.
May 12 14:23:51 localhost systemd: Starting Show Plymouth Boot Screen...
May 12 14:23:51 localhost kernel: e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
May 12 14:23:51 localhost kernel: e1000: Copyright (c) 1999-2006 Intel Corporation.
May 12 14:23:51 localhost kernel: tsc: Refined TSC clocksource calibration: 2792.350 MHz
May 12 14:23:51 localhost systemd: Started Show Plymouth Boot Screen.
May 12 14:23:51 localhost systemd: Started Dispatch Password Requests to Console Directory Watch.
May 12 14:23:51 localhost systemd: Starting Paths.
May 12 14:23:51 localhost systemd: Reached target Paths.
May 12 14:23:51 localhost systemd: Starting Forward Password Requests to Plymouth Directory Watch.
May 12 14:23:51 localhost systemd: Started Forward Password Requests to Plymouth Directory Watch.
May 12 14:23:51 localhost systemd: Starting Basic System.
May 12 14:23:51 localhost systemd: Reached target Basic System.
May 12 14:23:51 localhost kernel: e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 08:00:27:19:ee:27
May 12 14:23:51 localhost kernel: e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
May 12 14:23:51 localhost kernel: scsi host0: ata_piix
May 12 14:23:51 localhost kernel: scsi host1: ata_piix
May 12 14:23:51 localhost kernel: ata1: PATA max UDMA/33 cmd 0x1f0 ctl 0x3f6 bmdma 0xd000 irq 14
May 12 14:23:51 localhost kernel: ata2: PATA max UDMA/33 cmd 0x170 ctl 0x376 bmdma 0xd008 irq 15
May 12 14:23:51 localhost kernel: ahci: SSS flag set, parallel bus scan disabled
May 12 14:23:51 localhost kernel: ahci 0000:00:0d.0: AHCI 0001.0100 32 slots 1 ports 3 Gbps 0x1 impl SATA mode
May 12 14:23:51 localhost kernel: ahci 0000:00:0d.0: flags: 64bit ncq stag only ccc
May 12 14:23:51 localhost kernel: scsi host2: ahci
May 12 14:23:51 localhost kernel: ata3: SATA max UDMA/133 abar m8192@0xf0842000 port 0xf0842100 irq 21
May 12 14:23:52 localhost kernel: e1000 0000:00:08.0 eth1: (PCI:33MHz:32-bit) 08:00:27:dd:5a:8c
May 12 14:23:52 localhost kernel: e1000 0000:00:08.0 eth1: Intel(R) PRO/1000 Network Connection
May 12 14:23:52 localhost systemd-udevd[233]: renamed network interface eth1 to enp0s8
May 12 14:23:52 localhost systemd-udevd[232]: renamed network interface eth0 to enp0s3
May 12 14:23:52 localhost kernel: ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
May 12 14:23:52 localhost kernel: ata3.00: ATA-6: VBOX HARDDISK, 1.0, max UDMA/133
May 12 14:23:52 localhost kernel: ata3.00: 134217728 sectors, multi 128: LBA48 NCQ (depth 31/32)
May 12 14:23:52 localhost kernel: ata3.00: configured for UDMA/133
May 12 14:23:52 localhost kernel: scsi 2:0:0:0: Direct-Access     ATA      VBOX HARDDISK    1.0  PQ: 0 ANSI: 5
May 12 14:23:52 localhost kernel: sd 2:0:0:0: [sda] 134217728 512-byte logical blocks: (68.7 GB/64.0 GiB)
May 12 14:23:52 localhost kernel: sd 2:0:0:0: [sda] Write Protect is off
May 12 14:23:52 localhost kernel: sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
May 12 14:23:52 localhost kernel: sda: sda1 sda2
May 12 14:23:52 localhost kernel: sd 2:0:0:0: [sda] Attached SCSI disk
May 12 14:23:52 localhost dracut-initqueue: Scanning devices sda2  for LVM logical volumes centos/root centos/swap
May 12 14:23:52 localhost dracut-initqueue: inactive '/dev/centos/swap' [2.00 GiB] inherit
May 12 14:23:52 localhost dracut-initqueue: inactive '/dev/centos/home' [20.16 GiB] inherit
May 12 14:23:52 localhost dracut-initqueue: inactive '/dev/centos/root' [41.29 GiB] inherit
May 12 14:23:52 localhost systemd: Found device /dev/mapper/centos-root.
May 12 14:23:52 localhost systemd: Starting File System Check on /dev/mapper/centos-root...
May 12 14:23:52 localhost systemd-fsck: /sbin/fsck.xfs: XFS file system.
May 12 14:23:52 localhost systemd: Started File System Check on /dev/mapper/centos-root.
May 12 14:23:52 localhost systemd: Started dracut initqueue hook.
May 12 14:23:52 localhost systemd: Started dracut pre-mount hook.
May 12 14:23:52 localhost systemd: Mounting /sysroot...
May 12 14:23:52 localhost systemd: Starting Remote File Systems (Pre).
May 12 14:23:52 localhost systemd: Reached target Remote File Systems (Pre).
May 12 14:23:52 localhost systemd: Starting Remote File Systems.
May 12 14:23:52 localhost systemd: Reached target Remote File Systems.
May 12 14:23:52 localhost kernel: SGI XFS with ACLs, security attributes, large block/inode numbers, no debug enabled
May 12 14:23:52 localhost kernel: XFS (dm-0): Mounting V4 Filesystem
May 12 14:23:52 localhost systemd: Mounted /sysroot.
May 12 14:23:52 localhost systemd: Starting Initrd Root File System.
May 12 14:23:52 localhost systemd: Reached target Initrd Root File System.
May 12 14:23:52 localhost systemd: Starting Reload Configuration from the Real Root...
May 12 14:23:52 localhost kernel: XFS (dm-0): Ending clean mount
May 12 14:23:52 localhost systemd: Reloading.
May 12 14:23:52 localhost systemd: Started Reload Configuration from the Real Root.
May 12 14:23:52 localhost systemd: Starting Initrd File Systems.
May 12 14:23:52 localhost systemd: Reached target Initrd File Systems.
May 12 14:23:52 localhost systemd: Started dracut mount hook.
May 12 14:23:52 localhost systemd: Starting Initrd Default Target.
May 12 14:23:52 localhost systemd: Reached target Initrd Default Target.
May 12 14:23:52 localhost systemd: Starting dracut pre-pivot and cleanup hook...
May 12 14:23:52 localhost systemd: Started dracut pre-pivot and cleanup hook.
May 12 14:23:52 localhost systemd: Starting Cleaning Up and Shutting Down Daemons...
May 12 14:23:52 localhost systemd: Stopping Cleaning Up and Shutting Down Daemons...
May 12 14:23:52 localhost systemd: Starting Plymouth switch root service...
May 12 14:23:52 localhost systemd: Stopped Cleaning Up and Shutting Down Daemons.
May 12 14:23:52 localhost systemd: Stopping dracut pre-pivot and cleanup hook...
May 12 14:23:52 localhost systemd: Stopped dracut pre-pivot and cleanup hook.
May 12 14:23:52 localhost systemd: Stopping Remote File Systems.
May 12 14:23:52 localhost systemd: Stopped target Remote File Systems.
May 12 14:23:52 localhost systemd: Stopping Remote File Systems (Pre).
May 12 14:23:52 localhost systemd: Stopped target Remote File Systems (Pre).
May 12 14:23:52 localhost systemd: Stopping dracut initqueue hook...
May 12 14:23:52 localhost systemd: Stopped dracut initqueue hook.
May 12 14:23:52 localhost systemd: Stopping Initrd Default Target.
May 12 14:23:52 localhost systemd: Stopped target Initrd Default Target.
May 12 14:23:52 localhost systemd: Stopping Basic System.
May 12 14:23:52 localhost systemd: Stopped target Basic System.
May 12 14:23:52 localhost systemd: Stopping Slices.
May 12 14:23:52 localhost systemd: Stopped target Slices.
May 12 14:23:52 localhost systemd: Stopping Paths.
May 12 14:23:52 localhost systemd: Stopped target Paths.
May 12 14:23:52 localhost systemd: Stopping Timers.
May 12 14:23:52 localhost systemd: Stopped target Timers.
May 12 14:23:52 localhost systemd: Stopping Sockets.
May 12 14:23:52 localhost systemd: Stopped target Sockets.
May 12 14:23:52 localhost systemd: Stopping System Initialization.
May 12 14:23:52 localhost systemd: Stopped target System Initialization.
May 12 14:23:52 localhost systemd: Stopping Apply Kernel Variables...
May 12 14:23:52 localhost systemd: Stopped Apply Kernel Variables.
May 12 14:23:52 localhost systemd: Stopping udev Coldplug all Devices...
May 12 14:23:52 localhost systemd: Stopped udev Coldplug all Devices.
May 12 14:23:52 localhost systemd: Stopping Swap.
May 12 14:23:52 localhost systemd: Stopped target Swap.
May 12 14:23:52 localhost systemd: Stopping Local File Systems.
May 12 14:23:52 localhost systemd: Stopped target Local File Systems.
May 12 14:23:52 localhost systemd: Stopping udev Kernel Device Manager...
May 12 14:23:52 localhost systemd: Stopped udev Kernel Device Manager.
May 12 14:23:52 localhost systemd: Stopping dracut pre-udev hook...
May 12 14:23:52 localhost systemd: Stopped dracut pre-udev hook.
May 12 14:23:52 localhost systemd: Stopping dracut cmdline hook...
May 12 14:23:52 localhost systemd: Stopped dracut cmdline hook.
May 12 14:23:52 localhost systemd: Stopping Create static device nodes in /dev...
May 12 14:23:52 localhost systemd: Stopped Create static device nodes in /dev.
May 12 14:23:52 localhost systemd: Stopping Create list of required static device nodes for the current kernel...
May 12 14:23:52 localhost systemd: Stopped Create list of required static device nodes for the current kernel.
May 12 14:23:52 localhost systemd: Stopping udev Kernel Socket.
May 12 14:23:52 localhost systemd: Closed udev Kernel Socket.
May 12 14:23:52 localhost systemd: Stopping udev Control Socket.
May 12 14:23:52 localhost systemd: Closed udev Control Socket.
May 12 14:23:52 localhost systemd: Starting Cleanup udevd DB...
May 12 14:23:52 localhost systemd: Started Plymouth switch root service.
May 12 14:23:52 localhost systemd: Started Cleanup udevd DB.
May 12 14:23:52 localhost systemd: Starting Switch Root.
May 12 14:23:52 localhost systemd: Reached target Switch Root.
May 12 14:23:52 localhost systemd: Starting Switch Root...
May 12 14:23:52 localhost systemd: Switching root.
May 12 14:23:52 localhost journal: Journal stopped
May 12 14:23:53 localhost journal: Runtime journal is using 8.0M (max allowed 189.5M, trying to leave 284.3M free of 1.8G available → current limit 189.5M).
May 12 14:23:53 localhost journal: Runtime journal is using 8.0M (max allowed 189.5M, trying to leave 284.3M free of 1.8G available → current limit 189.5M).
May 12 14:23:53 localhost systemd-journald[82]: Received SIGTERM
May 12 14:23:53 localhost kernel: type=1403 audit(1463063033.133:2): policy loaded auid=4294967295 ses=4294967295
May 12 14:23:53 localhost systemd[1]: Successfully loaded SELinux policy in 230.465ms.
May 12 14:23:53 localhost kernel: ip_tables: (C) 2000-2006 Netfilter Core Team
May 12 14:23:53 localhost systemd[1]: Inserted module 'ip_tables'
May 12 14:23:53 localhost systemd[1]: Relabelled /dev and /run in 27.139ms.
May 12 14:23:53 localhost journal: Journal started
May 12 14:23:53 localhost systemd: systemd 219 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
May 12 14:23:53 localhost systemd: Detected virtualization kvm.
May 12 14:23:53 localhost systemd: Detected architecture x86-64.
May 12 14:23:53 localhost systemd: Set hostname to <localhost.localdomain>.
May 12 14:23:53 localhost systemd: Configuration file /usr/lib/systemd/system/auditd.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
May 12 14:23:53 localhost systemd: Started Create list of required static device nodes for the current kernel.
May 12 14:23:53 localhost systemd: Started Remount Root and Kernel File Systems.
May 12 14:23:53 localhost systemd: Started Apply Kernel Variables.
May 12 14:23:53 localhost systemd: Started LVM2 metadata daemon.
May 12 14:23:53 localhost systemd: Starting LVM2 metadata daemon...
May 12 14:23:53 localhost systemd: Started Rebuild Dynamic Linker Cache.
May 12 14:23:53 localhost systemd: Started First Boot Wizard.
May 12 14:23:53 localhost systemd: Started Rebuild Hardware Database.
May 12 14:23:53 localhost systemd: Starting udev Coldplug all Devices...
May 12 14:23:53 localhost systemd: Starting Configure read-only root support...
May 12 14:23:53 localhost systemd: Starting Load/Save Random Seed...
May 12 14:23:53 localhost systemd: Starting Create Static Device Nodes in /dev...
May 12 14:23:53 localhost systemd: Starting Flush Journal to Persistent Storage...
May 12 14:23:53 localhost systemd: Started Load/Save Random Seed.
May 12 14:23:53 localhost journal: Runtime journal is using 8.0M (max allowed 189.5M, trying to leave 284.3M free of 1.8G available → current limit 189.5M).
May 12 14:23:53 localhost systemd: Started Flush Journal to Persistent Storage.
May 12 14:23:53 localhost systemd: Started udev Coldplug all Devices.
May 12 14:23:53 localhost systemd: Started Create Static Device Nodes in /dev.
May 12 14:23:53 localhost systemd: Reached target Local File Systems (Pre).
May 12 14:23:53 localhost systemd: Starting Local File Systems (Pre).
May 12 14:23:53 localhost systemd: Starting udev Kernel Device Manager...
May 12 14:23:53 localhost systemd-udevd: starting version 219
May 12 14:23:53 localhost lvm: 2 logical volume(s) in volume group "centos" monitored
May 12 14:23:53 localhost systemd: Started Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling.
May 12 14:23:53 localhost systemd: Started Configure read-only root support.
May 12 14:23:53 localhost systemd: Started udev Kernel Device Manager.
May 12 14:23:53 localhost kernel: piix4_smbus 0000:00:07.0: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr
May 12 14:23:54 localhost kernel: vboxguest: module verification failed: signature and/or required key missing - tainting kernel
May 12 14:23:54 localhost kernel: vgdrvHeartbeatInit: Setting up heartbeat to trigger every 2000 milliseconds
May 12 14:23:54 localhost kernel: ACPI: Video Device [GFX0] (multi-head: yes  rom: no  post: no)
May 12 14:23:54 localhost kernel: input: Video Bus as /devices/LNXSYSTM:00/device:00/PNP0A03:00/LNXVIDEO:00/input/input4
May 12 14:23:54 localhost kernel: input: Unspecified device as /devices/pci0000:00/0000:00:04.0/input/input5
May 12 14:23:54 localhost kernel: vboxguest: misc device minor 58, IRQ 20, I/O port d020, MMIO at 00000000f0400000 (size 0x400000)
May 12 14:23:54 localhost kernel: [drm] Initialized drm 1.1.0 20060810
May 12 14:23:54 localhost kernel: [drm] Initialized vboxvideo 1.0.0 20090303 for 0000:00:02.0 on minor 0
May 12 14:23:54 localhost kernel: sd 2:0:0:0: Attached scsi generic sg0 type 0
May 12 14:23:54 localhost kernel: input: PC Speaker as /devices/platform/pcspkr/input/input6
May 12 14:23:54 localhost systemd: Created slice system-lvm2\x2dpvscan.slice.
May 12 14:23:54 localhost systemd: Starting system-lvm2\x2dpvscan.slice.
May 12 14:23:54 localhost systemd: Starting LVM2 PV scan on device 8:2...
May 12 14:23:54 localhost kernel: alg: No test for __gcm-aes-aesni (__driver-gcm-aes-aesni)
May 12 14:23:54 localhost systemd: Found device VBOX_HARDDISK 1.
May 12 14:23:54 localhost systemd: Mounting /boot...
May 12 14:23:54 localhost kernel: ppdev: user-space parallel port driver
May 12 14:23:54 localhost kernel: XFS (sda1): Mounting V4 Filesystem
May 12 14:23:54 localhost systemd: Found device /dev/mapper/centos-swap.
May 12 14:23:54 localhost systemd: Activating swap /dev/mapper/centos-swap...
May 12 14:23:54 localhost kernel: Adding 2097148k swap on /dev/mapper/centos-swap.  Priority:-1 extents:1 across:2097148k FS
May 12 14:23:54 localhost systemd: Activated swap /dev/mapper/centos-swap.
May 12 14:23:54 localhost systemd: Reached target Swap.
May 12 14:23:54 localhost systemd: Starting Swap.
May 12 14:23:54 localhost kernel: alg: No test for crc32 (crc32-pclmul)
May 12 14:23:54 localhost lvm: 3 logical volume(s) in volume group "centos" now active
May 12 14:23:54 localhost systemd: Started LVM2 PV scan on device 8:2.
May 12 14:23:54 localhost systemd: Found device /dev/mapper/centos-home.
May 12 14:23:54 localhost systemd: Mounting /home...
May 12 14:23:54 localhost kernel: intel_rapl: domain package energy ctr 0:0 not working, skip
May 12 14:23:54 localhost kernel: XFS (dm-2): Mounting V4 Filesystem
May 12 14:23:54 localhost kernel: intel_rapl: domain core energy ctr 0:0 not working, skip
May 12 14:23:55 localhost kernel: intel_rapl: domain uncore energy ctr 0:0 not working, skip
May 12 14:23:55 localhost kernel: intel_rapl: no valid rapl domains found in package 0
May 12 14:23:55 localhost kernel: XFS (dm-2): Ending clean mount
May 12 14:23:55 localhost systemd: Mounted /home.
May 12 14:23:55 localhost kernel: XFS (sda1): Ending clean mount
May 12 14:23:55 localhost systemd: Mounted /boot.
May 12 14:23:55 localhost systemd: Reached target Local File Systems.
May 12 14:23:55 localhost systemd: Starting Local File Systems.
May 12 14:23:55 localhost systemd: Started Commit a transient machine-id on disk.
May 12 14:23:55 localhost systemd: Started Relabel all filesystems, if necessary.
May 12 14:23:55 localhost systemd: Starting Tell Plymouth To Write Out Runtime Data...
May 12 14:23:55 localhost systemd: Started Mark the need to relabel after reboot.
May 12 14:23:55 localhost systemd: Started Rebuild Journal Catalog.
May 12 14:23:55 localhost systemd: Starting Import network configuration from initramfs...
May 12 14:23:55 localhost systemd: Started Reconfigure the system on administrator request.
May 12 14:23:55 localhost systemd: Started Update is Completed.
May 12 14:23:55 localhost systemd: Started Tell Plymouth To Write Out Runtime Data.
May 12 14:23:55 localhost systemd: Started Import network configuration from initramfs.
May 12 14:23:55 localhost systemd: Starting Create Volatile Files and Directories...
May 12 14:23:55 localhost systemd: Started Create Volatile Files and Directories.
May 12 14:23:55 localhost systemd: Starting Security Auditing Service...
May 12 14:23:56 localhost auditd[568]: Started dispatcher: /sbin/audispd pid: 578
May 12 14:23:56 localhost kernel: type=1305 audit(1463063036.009:3): audit_pid=568 old=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1
May 12 14:23:56 localhost audispd: No plugins found, exiting
May 12 14:23:56 localhost augenrules: /sbin/augenrules: No change
May 12 14:23:56 localhost auditd[568]: Init complete, auditd 2.4.1 listening for events (startup state enable)
May 12 14:23:56 localhost augenrules: No rules
May 12 14:23:56 localhost augenrules: enabled 1
May 12 14:23:56 localhost augenrules: flag 1
May 12 14:23:56 localhost augenrules: pid 568
May 12 14:23:56 localhost augenrules: rate_limit 0
May 12 14:23:56 localhost augenrules: backlog_limit 320
May 12 14:23:56 localhost augenrules: lost 0
May 12 14:23:56 localhost augenrules: backlog 1
May 12 14:23:56 localhost systemd: Started Security Auditing Service.
May 12 14:23:56 localhost systemd: Starting Update UTMP about System Boot/Shutdown...
May 12 14:23:56 localhost systemd: Started Update UTMP about System Boot/Shutdown.
May 12 14:23:56 localhost systemd: Reached target System Initialization.
May 12 14:23:56 localhost systemd: Starting System Initialization.
May 12 14:23:56 localhost systemd: Starting Docker Socket for the API.
May 12 14:23:56 localhost systemd: Started Flexible branding.
May 12 14:23:56 localhost systemd: Starting Flexible branding.
May 12 14:23:56 localhost systemd: Reached target Paths.
May 12 14:23:56 localhost systemd: Starting Paths.
May 12 14:23:56 localhost systemd: Listening on RPCbind Server Activation Socket.
May 12 14:23:56 localhost systemd: Starting RPCbind Server Activation Socket.
May 12 14:23:56 localhost systemd: Started Daily Cleanup of Temporary Directories.
May 12 14:23:56 localhost systemd: Starting Daily Cleanup of Temporary Directories.
May 12 14:23:56 localhost systemd: Reached target Timers.
May 12 14:23:56 localhost systemd: Starting Timers.
May 12 14:23:56 localhost systemd: Listening on D-Bus System Message Bus Socket.
May 12 14:23:56 localhost systemd: Starting D-Bus System Message Bus Socket.
May 12 14:23:56 localhost systemd: Listening on Docker Socket for the API.
May 12 14:23:56 localhost systemd: Reached target Sockets.
May 12 14:23:56 localhost systemd: Starting Sockets.
May 12 14:23:56 localhost systemd: Reached target Basic System.
May 12 14:23:56 localhost systemd: Starting Basic System.
May 12 14:23:56 localhost systemd: Starting vboxadd.service...
May 12 14:23:56 localhost systemd: Starting Dump dmesg to /var/log/dmesg...
May 12 14:23:56 localhost systemd: Starting Dynamic System Tuning Daemon...
May 12 14:23:56 localhost systemd: Started OpenSSH Server Key Generation.
May 12 14:23:56 localhost systemd: Starting System Logging Service...
May 12 14:23:56 localhost systemd: Started Load CPU microcode update.
May 12 14:23:56 localhost systemd: Starting Login Service...
May 12 14:23:56 localhost systemd: Starting vboxadd-x11.service...
May 12 14:23:56 localhost systemd: Starting Network Manager...
May 12 14:23:56 localhost systemd: Starting Permit User Sessions...
May 12 14:23:56 localhost systemd: Started D-Bus System Message Bus.
May 12 14:23:56 localhost systemd: Starting D-Bus System Message Bus...
May 12 14:23:56 localhost systemd: Started System Logging Service.
May 12 14:23:56 localhost systemd: Started Dump dmesg to /var/log/dmesg.
May 12 14:23:56 localhost systemd: Started Permit User Sessions.
May 12 14:23:56 localhost systemd-logind: Watching system buttons on /dev/input/event0 (Power Button)
May 12 14:23:56 localhost systemd-logind: Watching system buttons on /dev/input/event1 (Sleep Button)
May 12 14:23:56 localhost systemd-logind: Watching system buttons on /dev/input/event4 (Video Bus)
May 12 14:23:56 localhost systemd-logind: New seat seat0.
May 12 14:23:56 localhost systemd: Started Login Service.
May 12 14:23:56 localhost systemd: Starting Wait for Plymouth Boot Screen to Quit...
May 12 14:23:56 localhost systemd: Starting Terminate Plymouth Boot Screen...
May 12 14:23:56 localhost NetworkManager[597]: <info>  NetworkManager (version 1.0.0-14.git20150121.b4ea599c.el7) is starting...
May 12 14:23:56 localhost NetworkManager[597]: <info>  Read config: /etc/NetworkManager/NetworkManager.conf and conf.d: 10-ibft-plugin.conf
May 12 14:23:56 localhost NetworkManager[597]: <info>  WEXT support is disabled
May 12 14:23:56 localhost systemd: Started Command Scheduler.
May 12 14:23:56 localhost systemd: Starting Command Scheduler...
May 12 14:23:56 localhost NetworkManager[597]: <info>  Acquired D-Bus service com.redhat.ifcfgrh1
May 12 14:23:56 localhost NetworkManager[597]: <info>  Loaded plugin ifcfg-rh: (c) 2007 - 2013 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
May 12 14:23:56 localhost systemd: Received SIGRTMIN+20 from PID 249 (plymouthd).
May 12 14:23:56 localhost systemd: Received SIGRTMIN+21 from PID 249 (plymouthd).
May 12 14:23:56 localhost NetworkManager[597]: <info>  Loaded plugin iBFT: (c) 2014 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
May 12 14:23:56 localhost NetworkManager[597]: <info>  Loaded plugin keyfile: (c) 2007 - 2013 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
May 12 14:23:56 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
May 12 14:23:56 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-enp0s3 ...
May 12 14:23:56 localhost NetworkManager[597]: <info>      read connection 'enp0s3'
May 12 14:23:56 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-enp0s8 ...
May 12 14:23:56 localhost NetworkManager[597]: <info>      read connection 'System enp0s8'
May 12 14:23:56 localhost NetworkManager[597]: <warn>      Ignoring connection 'System enp0s8' / device 'enp0s8' due to NM_CONTROLLED=no.
May 12 14:23:56 localhost NetworkManager[597]: <info>  monitoring kernel firmware directory '/lib/firmware'.
May 12 14:23:56 localhost systemd: Started Terminate Plymouth Boot Screen.
May 12 14:23:56 localhost systemd: Started Wait for Plymouth Boot Screen to Quit.
May 12 14:23:56 localhost NetworkManager[597]: <info>  Loaded device plugin: /usr/lib64/NetworkManager/libnm-device-plugin-team.so
May 12 14:23:56 localhost NetworkManager[597]: <info>  WiFi enabled by radio killswitch; enabled by state file
May 12 14:23:56 localhost NetworkManager[597]: <info>  WWAN enabled by radio killswitch; enabled by state file
May 12 14:23:56 localhost NetworkManager[597]: <info>  WiMAX enabled by radio killswitch; enabled by state file
May 12 14:23:56 localhost NetworkManager[597]: <info>  Networking is enabled by state file
May 12 14:23:56 localhost NetworkManager[597]: <info>  (lo): link connected
May 12 14:23:56 localhost systemd: Started Getty on tty1.
May 12 14:23:56 localhost NetworkManager[597]: <info>  (lo): carrier is ON
May 12 14:23:56 localhost systemd: Starting Getty on tty1...
May 12 14:23:56 localhost NetworkManager[597]: <info>  (lo): new Generic device (driver: 'unknown' ifindex: 1)
May 12 14:23:56 localhost systemd: Reached target Login Prompts.
May 12 14:23:56 localhost systemd: Starting Login Prompts.
May 12 14:23:56 localhost NetworkManager[597]: <info>  (lo): exported as /org/freedesktop/NetworkManager/Devices/0
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): carrier is OFF
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): new Ethernet device (driver: 'e1000' ifindex: 2)
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): exported as /org/freedesktop/NetworkManager/Devices/1
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
May 12 14:23:56 localhost kernel: IPv6: ADDRCONF(NETDEV_UP): enp0s3: link is not ready
May 12 14:23:56 localhost kernel: e1000: enp0s3 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
May 12 14:23:56 localhost systemd: Started vboxadd-x11.service.
May 12 14:23:56 localhost systemd: Started Network Manager.
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): link connected
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): preparing device
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s8): carrier is OFF
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s8): new Ethernet device (driver: 'e1000' ifindex: 3)
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s8): exported as /org/freedesktop/NetworkManager/Devices/2
May 12 14:23:56 localhost dbus[599]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
May 12 14:23:56 localhost dbus-daemon: dbus[599]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
May 12 14:23:56 localhost systemd: Starting Authorization Manager...
May 12 14:23:56 localhost systemd: Starting Network Manager Wait Online...
May 12 14:23:56 localhost NetworkManager[597]: <info>  Auto-activating connection 'enp0s3'.
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: starting connection 'enp0s3'
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 1 of 5 (Device Prepare) scheduled...
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 1 of 5 (Device Prepare) started...
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): device state change: disconnected -> prepare (reason 'none') [30 40 0]
May 12 14:23:56 localhost NetworkManager[597]: <info>  NetworkManager state is now CONNECTING
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 2 of 5 (Device Configure) scheduled...
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 1 of 5 (Device Prepare) complete.
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 2 of 5 (Device Configure) starting...
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): device state change: prepare -> config (reason 'none') [40 50 0]
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 2 of 5 (Device Configure) successful.
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 2 of 5 (Device Configure) complete.
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 3 of 5 (IP Configure Start) scheduled.
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 3 of 5 (IP Configure Start) started...
May 12 14:23:56 localhost NetworkManager[597]: <info>  (enp0s3): device state change: config -> ip-config (reason 'none') [50 70 0]
May 12 14:23:56 localhost NetworkManager[597]: <info>  Activation (enp0s3) Beginning DHCPv4 transaction (timeout in 45 seconds)
May 12 14:23:57 localhost kernel: floppy0: no floppy controllers found
May 12 14:23:57 localhost kernel: work still pending
May 12 14:23:57 localhost polkitd[642]: Started polkitd version 0.112
May 12 14:23:57 localhost dbus-daemon: dbus[599]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
May 12 14:23:57 localhost dbus[599]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
May 12 14:23:57 localhost systemd: Started Authorization Manager.
May 12 14:23:57 localhost NetworkManager[597]: <info>  dhclient started with pid 645
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 3 of 5 (IP Configure Start) complete.
May 12 14:23:57 localhost vboxadd: Starting the VirtualBox Guest Additions [  OK  ]
May 12 14:23:57 localhost systemd: Started vboxadd.service.
May 12 14:23:57 localhost systemd: Starting vboxadd-service.service...
May 12 14:23:57 localhost dhclient[645]: DHCPREQUEST on enp0s3 to 255.255.255.255 port 67 (xid=0x61bfb47a)
May 12 14:23:57 localhost dhclient[645]: DHCPACK from 10.0.2.2 (xid=0x61bfb47a)
May 12 14:23:57 localhost NetworkManager[597]: <info>    address 10.0.2.15
May 12 14:23:57 localhost NetworkManager[597]: <info>    plen 24 (255.255.255.0)
May 12 14:23:57 localhost NetworkManager[597]: <info>    gateway 10.0.2.2
May 12 14:23:57 localhost NetworkManager[597]: <info>    server identifier 10.0.2.2
May 12 14:23:57 localhost NetworkManager[597]: <info>    lease time 86400
May 12 14:23:57 localhost NetworkManager[597]: <info>    nameserver '10.0.2.3'
May 12 14:23:57 localhost NetworkManager[597]: <info>    domain name 'hack.id.au'
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): DHCPv4 state changed unknown -> bound
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 5 of 5 (IPv4 Configure Commit) scheduled...
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 5 of 5 (IPv4 Commit) started...
May 12 14:23:57 localhost dhclient[645]: bound to 10.0.2.15 -- renewal in 37139 seconds.
May 12 14:23:57 localhost NetworkManager[597]: _nl_get_vtable: assertion 'vtable.handle' failed
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 5 of 5 (IPv4 Commit) complete.
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): device state change: secondaries -> activated (reason 'none') [90 100 0]
May 12 14:23:57 localhost NetworkManager[597]: <info>  NetworkManager state is now CONNECTED_LOCAL
May 12 14:23:57 localhost NetworkManager[597]: <info>  NetworkManager state is now CONNECTED_GLOBAL
May 12 14:23:57 localhost NetworkManager[597]: <info>  Policy set 'enp0s3' (enp0s3) as default for IPv4 routing and DNS.
May 12 14:23:57 localhost NetworkManager[597]: <info>  (enp0s3): Activation: successful, device activated.
May 12 14:23:57 localhost dbus-daemon: dbus[599]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
May 12 14:23:57 localhost dbus[599]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
May 12 14:23:57 localhost systemd: Starting Network Manager Script Dispatcher Service...
May 12 14:23:57 localhost kernel: VBoxService 5.0.16 r105871 (verbosity: 0) linux.amd64 (Mar  4 2016 17:38:55) release log
00:00:00.000195 main     Log opened 2016-05-12T14:23:57.811621000Z
May 12 14:23:57 localhost kernel: 00:00:00.000324 main     OS Product: Linux
May 12 14:23:57 localhost kernel: 00:00:00.000374 main     OS Release: 3.10.0-229.el7.x86_64
May 12 14:23:57 localhost kernel: 00:00:00.000429 main     OS Version: #1 SMP Fri Mar 6 11:36:42 UTC 2015
May 12 14:23:57 localhost kernel: 00:00:00.000491 main     Executable: /opt/VBoxGuestAdditions-5.0.16/sbin/VBoxService
00:00:00.000493 main     Process ID: 676
00:00:00.000493 main     Package type: LINUX_64BITS_GENERIC
May 12 14:23:57 localhost kernel: 00:00:00.007678 main     5.0.16 r105871 started. Verbose level = 0
May 12 14:23:57 localhost vboxadd-service: Starting VirtualBox Guest Addition service [  OK  ]
May 12 14:23:57 localhost systemd: Started vboxadd-service.service.
May 12 14:23:57 localhost dbus-daemon: dbus[599]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 12 14:23:57 localhost dbus[599]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 12 14:23:57 localhost systemd: Started Network Manager Script Dispatcher Service.
May 12 14:23:57 localhost nm-dispatcher: Dispatching action 'up' for enp0s3
May 12 14:23:58 localhost systemd: Started Dynamic System Tuning Daemon.
May 12 14:24:01 localhost NetworkManager[597]: <info>  startup complete
May 12 14:24:01 localhost systemd: Started Network Manager Wait Online.
May 12 14:24:01 localhost systemd: Starting LSB: Bring up/down networking...
May 12 14:24:02 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
May 12 14:24:02 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
May 12 14:24:02 localhost network: Bringing up loopback interface:  Could not load file '/etc/sysconfig/network-scripts/ifcfg-lo'
May 12 14:24:02 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
May 12 14:24:02 localhost network: Could not load file '/etc/sysconfig/network-scripts/ifcfg-lo'
May 12 14:24:02 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
May 12 14:24:02 localhost network: Could not load file '/etc/sysconfig/network-scripts/ifcfg-lo'
May 12 14:24:02 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
May 12 14:24:02 localhost network: Could not load file '/etc/sysconfig/network-scripts/ifcfg-lo'
May 12 14:24:02 localhost network: [  OK  ]
May 12 14:24:02 localhost network: Bringing up interface enp0s3:  [  OK  ]
May 12 14:24:02 localhost kernel: IPv6: ADDRCONF(NETDEV_UP): enp0s8: link is not ready
May 12 14:24:02 localhost kernel: e1000: enp0s8 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
May 12 14:24:02 localhost kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp0s8: link becomes ready
May 12 14:24:02 localhost NetworkManager[597]: <info>  (enp0s8): link connected
May 12 14:24:05 localhost network: Bringing up interface enp0s8:  [  OK  ]
May 12 14:24:05 localhost systemd: Started LSB: Bring up/down networking.
May 12 14:24:05 localhost systemd: Reached target Network.
May 12 14:24:05 localhost systemd: Starting Network.
May 12 14:24:05 localhost systemd: Starting Postfix Mail Transport Agent...
May 12 14:24:05 localhost systemd: Starting Docker Application Container Engine...
May 12 14:24:05 localhost systemd: Started OpenSSH server daemon.
May 12 14:24:05 localhost systemd: Starting OpenSSH server daemon...
May 12 14:24:05 localhost systemd: Reached target Network is Online.
May 12 14:24:05 localhost systemd: Starting Network is Online.
May 12 14:24:05 localhost systemd: Starting LSB: Supports the direct execution of binary formats....
May 12 14:24:05 localhost systemd: Starting Crash recovery kernel arming...
May 12 14:24:05 localhost systemd: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 980 (jexec)
May 12 14:24:05 localhost systemd: Mounting Arbitrary Executable File Formats File System...
May 12 14:24:05 localhost systemd: Mounted Arbitrary Executable File Formats File System.
May 12 14:24:05 localhost jexec: Starting jexec services
May 12 14:24:05 localhost systemd: Started LSB: Supports the direct execution of binary formats..
May 12 14:24:05 localhost kernel: loop: module loaded
May 12 14:24:06 localhost docker: time="2016-05-12T14:24:06.218780487Z" level=warning msg="devmapper: Usage of loopback devices is strongly discouraged for production use. Please use `--storage-opt dm.thinpooldev` or use `man docker` to refer to dm.thinpooldev section."
May 12 14:24:06 localhost systemd: Device dev-disk-by\x2duuid-6231c89a\x2d6ffa\x2d40ba\x2d999c\x2d28c3f826c59e.device appeared twice with different sysfs paths /sys/devices/virtual/block/loop0 and /sys/devices/virtual/block/dm-4
May 12 14:24:06 localhost docker: time="2016-05-12T14:24:06.376993896Z" level=warning msg="devmapper: Base device already exists and has filesystem xfs on it. User specified filesystem  will be ignored."
May 12 14:24:06 localhost systemd: Created slice user-1000.slice.
May 12 14:24:06 localhost systemd: Starting user-1000.slice.
May 12 14:24:06 localhost systemd: Started Session 1 of user vagrant.
May 12 14:24:06 localhost systemd-logind: New session 1 of user vagrant.
May 12 14:24:06 localhost docker: time="2016-05-12T14:24:06.427050808Z" level=info msg="[graphdriver] using prior storage driver \"devicemapper\""
May 12 14:24:06 localhost systemd: Starting Session 1 of user vagrant.
May 12 14:24:06 localhost docker: time="2016-05-12T14:24:06.588364792Z" level=info msg="Graph migration to content-addressability took 0.00 seconds"
May 12 14:24:06 localhost kernel: Bridge firewalling registered
May 12 14:24:06 localhost docker: time="2016-05-12T14:24:06.624737748Z" level=warning msg="Running modprobe bridge br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.\ninsmod /lib/modules/3.10.0-229.el7.x86_64/kernel/net/llc/llc.ko \ninsmod /lib/modules/3.10.0-229.el7.x86_64/kernel/net/802/stp.ko \ninsmod /lib/modules/3.10.0-229.el7.x86_64/kernel/net/bridge/bridge.ko \n, error: exit status 1"
May 12 14:24:06 localhost kernel: nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
May 12 14:24:06 localhost docker: time="2016-05-12T14:24:06.662182820Z" level=info msg="Firewalld running: false"
May 12 14:24:06 localhost systemd: Started Postfix Mail Transport Agent.
May 12 14:24:07 localhost docker: time="2016-05-12T14:24:07.058787036Z" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address"
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): carrier is OFF
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): new Bridge device (driver: 'bridge' ifindex: 4)
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): exported as /org/freedesktop/NetworkManager/Devices/3
May 12 14:24:07 localhost kernel: IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
May 12 14:24:07 localhost NetworkManager[597]: <info>      read connection 'docker0'
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): device state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: starting connection 'docker0'
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 1 of 5 (Device Prepare) scheduled...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 1 of 5 (Device Prepare) started...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 2 of 5 (Device Configure) scheduled...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 1 of 5 (Device Prepare) complete.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 2 of 5 (Device Configure) starting...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): device state change: prepare -> config (reason 'none') [40 50 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 2 of 5 (Device Configure) successful.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 3 of 5 (IP Configure Start) scheduled.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 2 of 5 (Device Configure) complete.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 3 of 5 (IP Configure Start) started...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): device state change: config -> ip-config (reason 'none') [50 70 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 5 of 5 (IPv4 Configure Commit) scheduled...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 3 of 5 (IP Configure Start) complete.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 5 of 5 (IPv4 Commit) started...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: Stage 5 of 5 (IPv4 Commit) complete.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): device state change: secondaries -> activated (reason 'none') [90 100 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): Activation: successful, device activated.
May 12 14:24:07 localhost nm-dispatcher: Dispatching action 'up' for docker0
May 12 14:24:07 localhost docker: time="2016-05-12T14:24:07.336093678Z" level=info msg="Loading containers: start."
May 12 14:24:07 localhost systemd: Device dev-disk-by\x2duuid-6231c89a\x2d6ffa\x2d40ba\x2d999c\x2d28c3f826c59e.device appeared twice with different sysfs paths /sys/devices/virtual/block/loop0 and /sys/devices/virtual/block/dm-4
May 12 14:24:07 localhost kernel: XFS (dm-4): Mounting V4 Filesystem
May 12 14:24:07 localhost kernel: XFS (dm-4): Ending clean mount
May 12 14:24:07 localhost kernel: device veth8ae31ac entered promiscuous mode
May 12 14:24:07 localhost kernel: IPv6: ADDRCONF(NETDEV_UP): veth8ae31ac: link is not ready
May 12 14:24:07 localhost kernel: docker0: port 1(veth8ae31ac) entered forwarding state
May 12 14:24:07 localhost kernel: docker0: port 1(veth8ae31ac) entered forwarding state
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8bae018): carrier is OFF
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8bae018): new Veth device (driver: 'unknown' ifindex: 5)
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8bae018): exported as /org/freedesktop/NetworkManager/Devices/4
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): carrier is OFF
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): new Veth device (driver: 'unknown' ifindex: 6)
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): exported as /org/freedesktop/NetworkManager/Devices/5
May 12 14:24:07 localhost NetworkManager[597]: <info>  (docker0): bridge port veth8ae31ac was attached
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): enslaved to docker0
May 12 14:24:07 localhost NetworkManager[597]: <info>      read connection 'veth8ae31ac'
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): device state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
May 12 14:24:07 localhost kernel: IPv6: ADDRCONF(NETDEV_CHANGE): docker0: link becomes ready
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: starting connection 'veth8ae31ac'
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 1 of 5 (Device Prepare) scheduled...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 1 of 5 (Device Prepare) started...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): device state change: disconnected -> prepare (reason 'none') [30 40 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 2 of 5 (Device Configure) scheduled...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 1 of 5 (Device Prepare) complete.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 2 of 5 (Device Configure) starting...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): device state change: prepare -> config (reason 'none') [40 50 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 2 of 5 (Device Configure) successful.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 3 of 5 (IP Configure Start) scheduled.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 2 of 5 (Device Configure) complete.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 3 of 5 (IP Configure Start) started...
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): device state change: config -> ip-config (reason 'none') [50 70 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: Stage 3 of 5 (IP Configure Start) complete.
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): device state change: secondaries -> activated (reason 'none') [90 100 0]
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): Activation: successful, device activated.
May 12 14:24:07 localhost nm-dispatcher: Dispatching action 'up' for veth8ae31ac
May 12 14:24:07 localhost kernel: IPv6: ADDRCONF(NETDEV_CHANGE): veth8ae31ac: link becomes ready
May 12 14:24:07 localhost NetworkManager[597]: <info>  (veth8ae31ac): link connected
May 12 14:24:07 localhost docker: .
May 12 14:24:07 localhost docker: time="2016-05-12T14:24:07.918847653Z" level=info msg="Loading containers: done."
May 12 14:24:07 localhost docker: time="2016-05-12T14:24:07.918875149Z" level=info msg="Daemon has completed initialization"
May 12 14:24:07 localhost docker: time="2016-05-12T14:24:07.918894195Z" level=info msg="Docker daemon" commit=20f81dd execdriver=native-0.2 graphdriver=devicemapper version=1.10.3
May 12 14:24:07 localhost systemd: Started Docker Application Container Engine.
May 12 14:24:07 localhost docker: time="2016-05-12T14:24:07.985860383Z" level=info msg="API listen on /var/run/docker.sock"
May 12 14:24:09 localhost kdumpctl: kexec: loaded kdump kernel
May 12 14:24:09 localhost kdumpctl: Starting kdump: [OK]
May 12 14:24:09 localhost systemd: Started Crash recovery kernel arming.
May 12 14:24:09 localhost systemd: Reached target Multi-User System.
May 12 14:24:09 localhost systemd: Starting Multi-User System.
May 12 14:24:09 localhost systemd: Starting Update UTMP about System Runlevel Changes...
May 12 14:24:09 localhost systemd: Started Stop Read-Ahead Data Collection 10s After Completed Startup.
May 12 14:24:09 localhost systemd: Started Update UTMP about System Runlevel Changes.
May 12 14:24:09 localhost systemd: Startup finished in 657ms (kernel) + 2.402s (initrd) + 16.298s (userspace) = 19.357s.
May 12 14:24:10 localhost NetworkManager[597]: <info>  parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
May 12 14:24:11 localhost NetworkManager[597]: <info>  (enp0s8): link disconnected
May 12 14:24:11 localhost kernel: IPv6: ADDRCONF(NETDEV_UP): enp0s8: link is not ready
May 12 14:24:11 localhost kernel: e1000: enp0s8 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
May 12 14:24:11 localhost kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp0s8: link becomes ready
May 12 14:24:11 localhost NetworkManager[597]: <info>  (enp0s8): link connected
May 12 14:24:14 localhost systemd: Started Session 2 of user vagrant.
May 12 14:24:14 localhost systemd-logind: New session 2 of user vagrant.
May 12 14:24:14 localhost systemd: Starting Session 2 of user vagrant.
May 12 14:24:22 localhost kernel: docker0: port 1(veth8ae31ac) entered forwarding state
May 12 14:24:28 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
May 12 14:24:28 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 4 of 5 (IPv6 Configure Timeout) started...
May 12 14:24:28 localhost NetworkManager[597]: <info>  (enp0s3): Activation: Stage 4 of 5 (IPv6 Configure Timeout) complete.
May 12 14:25:10 localhost docker: time="2016-05-12T14:25:10.898745229Z" level=error msg="Handler for POST /v1.22/containers/registry/start returned error: Container already started"
TylerJewell commented 8 years ago

I don't see anything helpful in the boot script.

The way Vagrant works is that provisioners are called in different times of the activation of the VM. The first script is only called when the VM is being created. The second script has an always tag, so it is called on every vagrant up, including the first activation of the VM and after resuming the VM from a suspend.

It seems that the script is not being called at all - or if it is, somehow it's not following through to complete and call the server. I'd very much like to diagnose this as we went from a situation where all was well to all wasn't.

HDC67 commented 8 years ago

I'm still here :). If only the second script runs, then this can't possibly work.

Where is the IDE started? The only place I see is after it times out trying to connect to it. Given that it never even tried to start it before that timeout happens, it will always timeout first.

The broken bit was when you suggested increasing the timeout as another timeout happened first and it bailed out completely without ever starting it. Reducing it back to the 11 (or at least less than 35), it still always times out but at least starts the IDE after the time out.

To me the script is fundamentally flawed in the sense it will always timeout, but will at least recover.

I think you need a 

export JAVA_HOME=/usr &>/dev/null
echo vagrant | sudo -S -E -u vagrant /home/vagrant/eclipse-che-*/bin/che.sh --remote:${IP} --skip:client -g start &>/tmp/1

...at the beginning of $script2 before the loop starts.

I am calling it quits now. If you really need to screen share I can possibly do that tomorrow.

TylerJewell commented 8 years ago

The /home/vagrant/eclipse-che-*/bin/che.sh is the command that starts the server. You don't want to call that script at the beginning of $script2 because in a suspend / resume scenario, the server is already running. It will cause unnecessary errors to initiate the server again.

My concern is that you said that when you did a vagrant destroy, vagrant up the server is no longer starting initially. That indicates something fundamental has changed if the java process is not getting launched. I'll look for you online when you first wake up in Australia.

TylerJewell commented 8 years ago

@ShonkyCH - One thing that we are experimenting with is a fundamentally different approach to the Vagrantfile. Instead of launching the server natively and then having to test it, we'd launch it within a Docker container. Docker containers are governed by a built-in daemon, which has auto-restart policies that can be applied. So the server would always be on.

We don't yet have a Docker container for the ARTIK IDE, but we do have one for Eclipse Che. It would be a simple exercise for us to generate a docker container for the ARTIK IDE. If you wanted to test this prototype Vagrantfile (attached), this is how the ARTIK IDE experience would be. You will need to lose the .txt extension when saving to your drive. I added it so that GitHub would upload it.

Vagrantfile.txt

HDC67 commented 8 years ago

OK fair enough re starting it outside the loop. However it means that if the VirtualBox VM is doing a clean boot then it will not start the IDE until the 1 minute timeout is up. Whilst it eventually works, like I said, this is flawed. It's not that $script2 doesn't run, it's that it does run just fine but has flawed logic when starting the IDE on a clean booted VM. I won't be the last person asking I'm sure.

You've misunderstood where I destroyed and started again. My point was that the increasing the timeout was futile as the IDE isn't started until after the timeout expires. If the timeout is increased you just wait longer and if increased too much, the overall timeout (counter = 35) expires first and the whole thing quits.

Again, there is no straight through path to start the IDE from a clean boot. It has to wait for the timeout after 1 minute. If I manually start it outside the loop as a test, mine's up in around 10 seconds (to start the IDE inside the VM).

An all in one docker sounds nice. You lost me a bit as I thought the current IDE was in a docker VM already running on the VirtualBox VM.

I would say this seems all rather complicated for an IDE. I realise it's different to a single installation on one machine but this setup seems a bit kludgy to be frank. I'm also not exactly impressed with the workflow once in the IDE. Is there a better place than github for discussions? The set up pages just direct to Github Issues which isn't a great place for discussions I think and clutters the issue tracker.

TylerJewell commented 8 years ago

Let's verify that we are looking at the same vagrantfile, please. What you are saying does it match what I am seeing. In the vagrantfile that is in master, on a clean boot the server is immediately booted. There is nothing in the logic that requires the script to delay a minute. So my guess is that we are seeing different logic. Let's bottom out on that.

This is the best location for discussions. If there is anything that derives into development issues we label it and track it as a long lived issue.

The vagrantfile, by the way, is merely provided as a way to more simply start the server. For the most flexibility and performance, you should run the server natively. We provide instructions on how to do that in the docs. The vagrantfile is just a simple way to make sure that the server starts the same way on anyone's computer. The native server version requires Java and docker to be setup on the computer and that is done differently on different operating systems. And Windows can cause some problems at times. So the vagrant approach is to get started rapidly.

Che uses docker to create the user workspaces. But running Che as a container is also possible. By doing that it gets rid of the need to do these server checks, restarts and the so forth.

HDC67 commented 8 years ago

I'm using the latest Vagrantfile from here: https://github.com/codenvy/artik-ide/blob/master/Vagrantfile

Tell me where in that file does a clean boot of the VM which only runs script2 start the IDE? The VM boots but the IDE doesn't get started until after the timeout.

I'm only at the getting started stage. If getting started is complex (not that this is overly complex), then the full version doesn't give me hope.

TylerJewell commented 8 years ago

Running as a server is not complex for most people but if you have Windows behind a firewall, on an old legacy network getting Java and docker installed can be challenging. So this vagrant solution is an abstraction for a lot of people that expect a product to just always install perfectly every time.

I think I see the confusion. While script 2 runs on every up, provision command, the first script only runs during the first creation of the VM.

At the end of the first script is the command to launch the server. This script is run and then the second one is run.

If you suspend the VM, and then vagrant up a second time, then only script 2 executes.

In the pure docker variation of this, we only have a single server command to call. Since docker runs as a daemon, the server will run quietly in the background and always be on when you need it.

TylerJewell commented 8 years ago

Since you are online right now, I am happy to do a screen share on a google hangout to discuss specifics. It can be easier to explain the nuances and get closure.

HDC67 commented 8 years ago

Basically yes that's what I've been saying for a few posts now.

If you suspend the VM, and then vagrant up a second time, then only script 2 executes.

Correct but also

If you shutdown the VM, and then vagrant up a second time, also only script 2 executes

Because of this, the IDE process isn't running and so it has to go through the timeout process because the vagrant file/script doesn't consider this situation.

Shutting down the VM was what started this. I'm not adverse to running a server although that would probably be in a VM anyway. I'm here but I have to go out very soon.

TylerJewell commented 8 years ago

Ok, so the scenarios that we tested were:

  1. Virgin: vagrant up
  2. Suspend: vagrant up, vagrant suspend, vagrant up
  3. Interrupt: vagrant up, then a hard reboot of the computer, vagrant up

What we did not test was:

  1. Shutdown: vagrant up, vagrant halt, vagrant up.

Is this your sequence?

The better way to solve this will be to package the server as a daemon with auto-restart inside of the VM. Then we do not need this silly logic. We can just have some basic tests to verify when the ARTIK IDE server is active or not.

HDC67 commented 8 years ago

3 will show the same issue.

I didn't do vagrant halt but it looks to be the same thing. I sent an ACPI shutdown directly in VirtualBox which caused a proper shutdown of the VM.

TylerJewell commented 8 years ago

Yes, confirmed in that situation. In scenario #3 the user does have to wait nearly a minute before the server reboot attempt is made. But to be somewhat fair, this thread started off with an immediate issue in that the server never restarted after a shutdown and vagrant up. The changes made were done quickly to provide a workaround for that scenario, which now works, though you have to wait the 60 seconds.

And the longer term solution will be to have it packaged as a docker container with a restart always policy, so that it's immediate and recycled in case of any interrupts.

You had indicated that on a clean boot of the VM, that the server wasn't starting at all, or that it was starting after a minute. I've filed an issue to get a Docker version of ARTIK IDE packaged. We'll have that in a couple days and this will be cleaner.

ddementieva commented 8 years ago

Multiple changes to Vagrantfile have been made. Closing the issue. Do not hesitate to reopen if you have more questions or face issues.