ubuntu-18.04-run_local_eve_adam.sh log-303-testing-20200225.log

by Inna Sosunova — last modified Feb 25, 2020 04:47 PM
application log icon ubuntu-18.04-run_local_eve_adam.sh log-303-testing-20200225.log — application log, 37 kB (38414 bytes)
File contents

root@eve:~# cd github/itmo-eve/eveadm
root@eve:~/github/itmo-eve/eveadm# git pull
Already up to date.
root@eve:~/github/itmo-eve/eveadm# ./tests/run_local_eve_adam.sh
========================================
Temp directory for test: /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr
========================================
Hit:1 http://ru.archive.ubuntu.com/ubuntu bionic InRelease
Get:2 http://ru.archive.ubuntu.com/ubuntu bionic-updates InRelease [88.7 kB]
Get:3 http://ru.archive.ubuntu.com/ubuntu bionic-backports InRelease [74.6 kB]
Get:4 http://ru.archive.ubuntu.com/ubuntu bionic-security InRelease [88.7 kB]
Ign:5 http://ubuntu-cloud.archive.canonical.com/ubuntu bionic-updates/train InRelease
Hit:6 http://ubuntu-cloud.archive.canonical.com/ubuntu bionic-updates/train Release
Fetched 252 kB in 1s (252 kB/s)
Reading package lists... Done
Building dependency tree
Reading state information... Done
All packages are up to date.
Reading package lists... Done
Building dependency tree
Reading state information... Done
Calculating upgrade... Done
The following packages were automatically installed and are no longer required:
  augeas-lenses libaugeas0 libbluetooth3 libnetcf1 libsdl1.2debian
Use 'apt autoremove' to remove them.
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
snap "go" is already installed, see 'snap help refresh'
Reading package lists... Done
Building dependency tree
Reading state information... Done
make is already the newest version (4.1-9.1ubuntu1).
telnet is already the newest version (0.17-41).
jq is already the newest version (1.5+dfsg-2).
git is already the newest version (1:2.17.1-1ubuntu0.5).
openssl is already the newest version (1.1.1-1ubuntu2.1~18.04.5).
docker.io is already the newest version (18.09.7-0ubuntu1~18.04.4).
qemu-system-x86 is already the newest version (1:4.0+dfsg-0ubuntu9.3~cloud0).
qemu-utils is already the newest version (1:4.0+dfsg-0ubuntu9.3~cloud0).
The following packages were automatically installed and are no longer required:
  augeas-lenses libaugeas0 libbluetooth3 libnetcf1 libsdl1.2debian
Use 'apt autoremove' to remove them.
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Cloning into 'eve'...
remote: Enumerating objects: 49501, done.
remote: Total 49501 (delta 0), reused 0 (delta 0), pack-reused 49501
Receiving objects: 100% (49501/49501), 57.53 MiB | 3.41 MiB/s, done.
Resolving deltas: 100% (31452/31452), done.
Checking out files: 100% (7345/7345), done.
Cloning into 'adam'...
remote: Enumerating objects: 676, done.
remote: Counting objects: 100% (676/676), done.
remote: Compressing objects: 100% (234/234), done.
remote: Total 676 (delta 435), reused 673 (delta 434), pack-reused 0
Receiving objects: 100% (676/676), 128.99 KiB | 810.00 KiB/s, done.
Resolving deltas: 100% (435/435), done.
========================================
Generate keypair for ssh (no overwrite if exists)
========================================
/root/.ssh/id_rsa already exists.
Overwrite (y/n)?
========================================
Prepare and run ADAM
========================================
docker build -t lfedge/adam .
Sending build context to Docker daemon  443.4kB
Step 1/17 : FROM golang:1.12.5-alpine3.9 AS build
 ---> c7330979841b
Step 2/17 : ENV CGO_ENABLED=0
 ---> Using cache
 ---> ab77a8669b02
Step 3/17 : ENV GO111MODULE=on
 ---> Using cache
 ---> ff5702020578
Step 4/17 : RUN apk --update add git
 ---> Using cache
 ---> a31b0f8f9b10
Step 5/17 : RUN mkdir -p /adam/src && mkdir -p /adam/bin
 ---> Using cache
 ---> 6634a94b82c7
Step 6/17 : WORKDIR /adam/src
 ---> Using cache
 ---> bb26f95be380
Step 7/17 : COPY go.mod .
 ---> Using cache
 ---> 47976a12189d
Step 8/17 : COPY go.sum .
 ---> Using cache
 ---> 1860df0fef18
Step 9/17 : RUN go mod download
 ---> Using cache
 ---> 519e44fe4024
Step 10/17 : COPY . /adam/src
 ---> a6796baf6696
Step 11/17 : ARG GOOS=linux
 ---> Running in ac3c31de2a9b
Removing intermediate container ac3c31de2a9b
 ---> 31f79e74d1d3
Step 12/17 : ARG GOARCH=amd64
 ---> Running in 2337a03d3d1c
Removing intermediate container 2337a03d3d1c
 ---> c86b5bfcaaa6
Step 13/17 : RUN go build -o /adam/bin/adam main.go
 ---> Running in 9a2d1f1887ac
Removing intermediate container 9a2d1f1887ac
 ---> 47293489b908
Step 14/17 : FROM scratch
 --->
Step 15/17 : COPY --from=build /adam/bin/adam /adam/bin/adam
 ---> Using cache
 ---> 5135958f11bc
Step 16/17 : WORKDIR /adam
 ---> Using cache
 ---> 1b6bf0227f1b
Step 17/17 : ENTRYPOINT ["/adam/bin/adam"]
 ---> Using cache
 ---> e121a61c199d
Successfully built e121a61c199d
Successfully tagged lfedge/adam:latest
Generating RSA private key, 4096 bit long modulus (2 primes)
.........................................................++++
..............................................................................................................................................................................++++
e is 65537 (0x010001)
Signature ok
subject=C = RU, ST = SPB, O = "MyOrg, Inc.", CN = mydomain.com
Getting CA Private Key
Signature ok
subject=C = RU, ST = SPB, O = "MyOrg, Inc.", CN = 07dddc46-6d0c-464d-8e5c-a5ac89396778
Getting CA Private Key
========================================
ADAM pid:
27853
========================================
========================================
Prepare and run EVE
========================================
Creating go builder image for user root
eve-build-root docker container is ready to use
mkdir -p /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/installer
cd /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/installer ; _() { C=`docker create $1 fake` ; shift ; docker export $C | tar -xf - "$@" ; docker rm $C ; } ; _ lfedge/eve-grub:6ba90a37e6f4d81a8a0c1d58f8eca99e72e19fdb-amd64 EFI
f0c9de6ab0f1e49ca9f4e83902519462d086d5d0e1ba23d5a67ab1de8c5efdfe
Done building /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/build-tools/bin/linuxkit
./tools/makerootfs.sh images/rootfs-xen.yml /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/installer/rootfs.img squash
Extract kernel image: lfedge/eve-kernel:0b58e0f9261e72839110c9f7c611f099c1062d6e-amd64
Add init containers:
Process init image: linuxkit/init:v0.5-amd64
Process init image: linuxkit/runc:v0.5-amd64
WARN[0022] targets/justin metadata is nearing expiry, you should re-sign the role metadata
WARN[0022] targets/riyaz metadata is nearing expiry, you should re-sign the role metadata
Process init image: linuxkit/containerd:v0.5-amd64
WARN[0027] targets/riyaz metadata is nearing expiry, you should re-sign the role metadata
Process init image: linuxkit/getty:v0.5-amd64
WARN[0032] targets/justin metadata is nearing expiry, you should re-sign the role metadata
Process init image: linuxkit/memlogd:v0.5-amd64
Process init image: lfedge/eve-grub:6ba90a37e6f4d81a8a0c1d58f8eca99e72e19fdb-amd64
Process init image: lfedge/eve-fw:e07c45a98386767ec3926b813dc4b46a96a81541-amd64
Process init image: lfedge/eve-xen:93b863e105118a0be7cf7423daf6b8831f0009d9-amd64
Process init image: lfedge/eve-gpt-tools:19ef56f5014fab1978a6e98b047d4498eabf8295-amd64
Process init image: lfedge/eve-dom0-ztools:ed3012e1703d8370c20645e94f9b57cb1202fac9-amd64
Add onboot containers:
  Create OCI config for lfedge/eve-storage-init:3524db08db611b060d8c2ac0ca2b5b4826e0c960-amd64
  Create OCI config for linuxkit/sysctl:v0.5-amd64
  Create OCI config for lfedge/eve-rngd:6e16dad8553a6c2939854abfa9f34a5f2604bce7-amd64
  Create OCI config for linuxkit/modprobe:v0.5-amd64
Add service containers:
  Create OCI config for lfedge/eve-rsyslog:0eda9ba176998eed3ca10503d2c72f6f9eccc13d-amd64
  Create OCI config for linuxkit/openntpd:v0.5-amd64
WARN[0081] targets/justin metadata is nearing expiry, you should re-sign the role metadata
WARN[0081] targets/riyaz metadata is nearing expiry, you should re-sign the role metadata
  Create OCI config for linuxkit/sshd:v0.5-amd64
WARN[0086] targets/justin metadata is nearing expiry, you should re-sign the role metadata
WARN[0086] targets/riyaz metadata is nearing expiry, you should re-sign the role metadata
  Create OCI config for lfedge/eve-wwan:2b98bc7569f167b1850dd9025a4b8c8489fee754-amd64
  Create OCI config for lfedge/eve-wlan:ac31bb78810451ef1333b3970f29bebc0a6c9c44-amd64
  Create OCI config for lfedge/eve-lisp:3aea807e87e2a4bdea34a5492bb85023bb0025df-amd64
  Create OCI config for lfedge/eve-guacd:f1f08a0fcadd35320f5d03fe0f0a1a318e8449be-amd64
  Create OCI config for itmoeve/eve-pillar:0fc650101bceb70e49662fa9789901de030d27c7-amd64
  Create OCI config for lfedge/eve-vtpm:11365a20a21fa000e9d48614e9303c8f0e81477f-amd64
  Create OCI config for lfedge/eve-watchdog:9a6307497cccb9a5e073fe71d54047d32f4fd963-amd64
Add files:
  /etc/eve-release
  /containers/services/pillar/lower/opt/zededa/bin/versioninfo
Parallel mksquashfs: Using 16 processors
Creating 4.0 filesystem on /rootfs.img, block size 131072.
[===========================================================/] 24435/24435 100%

Exportable Squashfs 4.0 filesystem, gzip compressed, data block size 131072
        compressed data, compressed metadata, compressed fragments, compressed xattrs
        duplicates are removed
Filesystem size 239807.57 Kbytes (234.19 Mbytes)
        33.05% of uncompressed filesystem size (725616.29 Kbytes)
Inode table size 268257 bytes (261.97 Kbytes)
        25.22% of uncompressed inode table size (1063487 bytes)
Directory table size 287295 bytes (280.56 Kbytes)
        44.99% of uncompressed directory table size (638545 bytes)
Number of duplicate files found 10678
Number of inodes 27971
Number of files 20160
Number of fragments 849
Number of symbolic links  5503
Number of device nodes 4
Number of fifo nodes 0
Number of socket nodes 0
Number of directories 2304
Number of ids (unique uids + gids) 3
Number of uids 1
        root (0)
Number of gids 3
        root (0)
        shadow (42)
        tty (5)
cd /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/installer ; _() { C=`docker create $1 fake` ; shift ; docker export $C | tar -xf - "$@" ; docker rm $C ; } ; _ lfedge/eve-mkimage-raw-efi:cf09472dd937fb0c7e040f8d338b0ddfd285bfcd-amd64 initrd.img EFI
28acf48a0eb971d14f23c23c234f0a953f8962cff01a834464c52029e5ae064d
./tools/makeconfig.sh ../adam/run/config/ /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/installer/config.img
1024+0 records in
1024+0 records out
mkfs.fat 4.1 (2017-01-24)
/config.img has 64 heads and 32 sectors per track,
hidden sectors 0x0000;
logical sector size is 512,
using 0xf8 media descriptor, with 2048 sectors;
drive number 0x80;
filesystem has 2 12-bit FATs and 4 sectors per cluster.
FAT size is 2 sectors, and provides 502 clusters.
There is 1 reserved sector.
Root directory contains 512 slots and uses 32 sectors.
Volume ID is f9537eeb, volume label EVE        .
./tools/makeflash.sh -C 8192 /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/installer /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/live.raw
1+0 records in
1+0 records out
1 byte copied, 0.000271607 s, 3.7 kB/s
Unknown (or unrecongnizable) GTP partition table on /output.img
Creating new GPT entries in memory.
Setting name!
partNum is 0
Setting name!
partNum is 1
Setting name!
partNum is 2
Setting name!
partNum is 3
Setting name!
partNum is 8
No problems found. 2014 free sectors (1007.0 KiB) available in 1
segments, the largest of which is 2014 (1007.0 KiB) in size.
mkdir -p /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64
qemu-img convert -c -f raw -O qcow2 /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/live.raw /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/live.qcow2
rm /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/live.raw
ln -s live.qcow2 /tmp/eveadam-2020-02-25-14-24-22-OfjNZTXXMr/eve/dist/amd64/live.img
========================================
EVE pid:
32068
========================================
Try to modify EVE config
========================================
You can connect to eve via telnet:
telnet localhost 49526
========================================
Trying again. Try #0
Trying again. Try #1
Trying again. Try #2
Trying again. Try #3
Trying again. Try #4
Trying again. Try #5
Trying again. Try #6
Trying again. Try #7
Trying again. Try #8
Trying again. Try #9
Trying again. Try #10
Trying again. Try #11
Trying again. Try #12
Trying again. Try #13
Trying again. Try #14
Trying again. Try #15
Trying again. Try #16
Trying again. Try #17
Trying again. Try #18
Trying again. Try #19
Trying again. Try #20
Trying again. Try #21
Trying again. Try #22
Trying again. Try #23
Trying again. Try #24
Trying again. Try #25
Trying again. Try #26
Trying again. Try #27
Trying again. Try #28
Trying again. Try #29
Failed to list devices!
========================================
You can connect to eve via telnet:
telnet localhost 49526
========================================
Do you want to try again? (y/n)y
Trying again. Try #0
Trying again. Try #1
Trying again. Try #2
Trying again. Try #3
Trying again. Try #4
Trying again. Try #5
Trying again. Try #6
Trying again. Try #7
Trying again. Try #8
Trying again. Try #9
Trying again. Try #10

Trying again. Try #11
Trying again. Try #12
Trying again. Try #13
Trying again. Try #14
Trying again. Try #15
Trying again. Try #16
Trying again. Try #17
Trying again. Try #18
Trying again. Try #19
Trying again. Try #20
Trying again. Try #21
Trying again. Try #22
Trying again. Try #23
Trying again. Try #24
Trying again. Try #25
Trying again. Try #26
Trying again. Try #27
Trying again. Try #28
Trying again. Try #29
Failed to list devices!
========================================
You can connect to eve via telnet:
telnet localhost 49526
========================================
Do you want to try again? (y/n)Please answer y or n.
Do you want to try again? (y/n)




root@eve:~# telnet localhost 49526
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.

linuxkit-525400123456:~# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 brd 127.255.255.255 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000
    link/ether 52:54:00:12:34:56 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::867:2024:fde6:7c85/64 scope link 
       valid_lft forever preferred_lft forever
3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000
    link/ether 52:54:00:12:34:57 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::e851:dab7:4f8c:a2a7/64 scope link 
       valid_lft forever preferred_lft forever
4: tunl0@NONE: <NOARP> mtu 1480 qdisc noop state DOWN qlen 1000
    link/ipip 0.0.0.0 brd 0.0.0.0
5: ip6tnl0@NONE: <NOARP> mtu 1452 qdisc noop state DOWN qlen 1000
    link/tunnel6 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00 brd 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
linuxkit-525400123456:~# eve enter
(ns: pillar) linuxkit-525400123456:/# 
(ns: pillar) linuxkit-525400123456:/# dhcpcd --noipv4ll -4 eth0 
DUID 00:01:00:01:25:e7:f1:e0:52:54:00:12:34:56
eth0: IAID 00:12:34:56
eth0: soliciting a DHCP lease
eth0: offered 192.168.0.10 from 192.168.0.2
eth0: probing address 192.168.0.10/24
eth0: leased 192.168.0.10 for 86400 seconds
eth0: adding route to 192.168.0.0/24
eth0: adding default route via 192.168.0.2
forked to background, child pid 4809
(ns: pillar) linuxkit-525400123456:/# dhcpcd --noipv4ll -4 eth1
DUID 00:01:00:01:25:e7:f1:e0:52:54:00:12:34:56
eth1: IAID 00:12:34:57
eth1: soliciting a DHCP lease
eth1: offered 192.168.3.10 from 192.168.3.2
eth1: probing address 192.168.3.10/24
eth1: leased 192.168.3.10 for 86400 seconds
eth1: adding route to 192.168.3.0/24
eth1: adding default route via 192.168.3.2
forked to background, child pid 4866
(ns: pillar) linuxkit-525400123456:/# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 brd 127.255.255.255 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 52:54:00:12:34:56 brd ff:ff:ff:ff:ff:ff
    inet 192.168.0.10/24 brd 192.168.0.255 scope global noprefixroute eth0
       valid_lft forever preferred_lft forever
    inet6 fe80::867:2024:fde6:7c85/64 scope link
       valid_lft forever preferred_lft forever
3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 52:54:00:12:34:57 brd ff:ff:ff:ff:ff:ff
    inet 192.168.3.10/24 brd 192.168.3.255 scope global noprefixroute eth1
       valid_lft forever preferred_lft forever
    inet6 fe80::e851:dab7:4f8c:a2a7/64 scope link
       valid_lft forever preferred_lft forever
4: tunl0@NONE: <NOARP> mtu 1480 qdisc noop state DOWN group default qlen 1000
    link/ipip 0.0.0.0 brd 0.0.0.0
5: ip6tnl0@NONE: <NOARP> mtu 1452 qdisc noop state DOWN group default qlen 1000
    link/tunnel6 :: brd ::
(ns: pillar) linuxkit-525400123456:/#
INFO: updated diag information at 2020-02-25T15:18:17.948384274Z
ERROR: Summary: Trying to connect to EV Controller
INFO: Using highest priority DevicePortConfig key lastresort
INFO: Have 2 total ports. 2 ports should be connected to EV controller
INFO: Port eth0: for EV Controller without usage-based charging 
INFO: eth0: IP address 192.168.0.10 not geolocated
INFO: eth0: DNS servers: 192.168.0.3,
INFO: eth0: no http(s) proxy
INFO: eth0: DNS lookup of mydomain.com returned 192.168.244.225 
INFO: eth0: mydomain.com:49228/api/v1/edgedevice/ping StatusOK  
ERROR: eth0: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth0: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth0: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth0: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth0: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth0: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth0: Exceeded 5 retries for get config
INFO: Port eth1: for EV Controller without usage-based charging 
INFO: eth1: IP address 192.168.3.10 not geolocated
INFO: eth1: DNS servers: 192.168.3.3,
INFO: eth1: no http(s) proxy
INFO: eth1: DNS lookup of mydomain.com returned 192.168.244.225 
INFO: eth1: mydomain.com:49228/api/v1/edgedevice/ping StatusOK  
ERROR: eth1: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth1: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth1: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth1: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth1: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth1: get mydomain.com:49228/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49228/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth1: Exceeded 5 retries for get config
WARNING: 0 out of 2 ports specified to have EV controller connectivity passed test

/opt/zededa/bin/diag
{"file":"/pillar/cmd/diag/diag.go:128","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.Run","level":"info","msg":"Starting diag","time":"2020-02-25T16:39:09.911511486Z"}
{"file":"/pillar/pubsub/legacy/legacy.go:22","func":"github.com/lf-edge/eve/pkg/pillar/pubsub/legacy.PublishPersistent","level":"info","msg":"legacy.PublishPersistent agentName()","time":"2020-02-25T16:39:09.93442989Z"}
{"file":"/pillar/pubsub/pubsub.go:187","func":"github.com/lf-edge/eve/pkg/pillar/pubsub.(*PubSub).publishImpl","level":"info","msg":"publishImpl agentName(), agentScope(), topic(GlobalConfig), nameString(/GlobalConfig), global(true), persistent(true)\n","time":"2020-02-25T16:39:09.936959135Z"}
{"file":"/pillar/pubsub/publish.go:180","func":"github.com/lf-edge/eve/pkg/pillar/pubsub.(*PublicationImpl).populate","level":"info","msg":"populate(/GlobalConfig)\n","time":"2020-02-25T16:39:09.938935939Z"}
{"file":"/pillar/pubsub/socketdriver/publish.go:62","func":"github.com/lf-edge/eve/pkg/pillar/pubsub/socketdriver.(*Publisher).Load","level":"info","msg":"Load(/GlobalConfig)\n","time":"2020-02-25T16:39:09.940484666Z"}
{"file":"/pillar/pubsub/socketdriver/publish.go:86","func":"github.com/lf-edge/eve/pkg/pillar/pubsub/socketdriver.(*Publisher).Load","level":"info","msg":"populate found key global file /persist/config//GlobalConfig/global.json\n","time":"2020-02-25T16:39:09.943126334Z"}
{"file":"/pillar/pubsub/publish.go:195","func":"github.com/lf-edge/eve/pkg/pillar/pubsub.(*PublicationImpl).populate","level":"info","msg":"populate(/GlobalConfig) done\n","time":"2020-02-25T16:39:09.946140537Z"}
{"file":"/pillar/pubsub/pubsub.go:198","func":"github.com/lf-edge/eve/pkg/pillar/pubsub.(*PubSub).publishImpl","level":"info","msg":"Publish(/GlobalConfig)\n","time":"2020-02-25T16:39:09.946942694Z"}
{"file":"/pillar/pubsub/pubsub.go:154","func":"github.com/lf-edge/eve/pkg/pillar/pubsub.(*PubSub).subscribeImpl","level":"info","msg":"Subscribe(/GlobalConfig)\n","time":"2020-02-25T16:39:09.948347894Z"}
{"file":"/pillar/watch/watchconfigstatus.go:177","func":"github.com/lf-edge/eve/pkg/pillar/watch.watchReadDir","level":"info","msg":"watchReadDir modified global.json","time":"2020-02-25T16:39:09.958702475Z"}
{"file":"/pillar/watch/watchconfigstatus.go:182","func":"github.com/lf-edge/eve/pkg/pillar/watch.watchReadDir","level":"info","msg":"watchReadDir done for /var/tmp/zededa//GlobalConfig\n","time":"2020-02-25T16:39:09.984732439Z"}
{"file":"/pillar/cmd/diag/diag.go:173","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.Run","level":"info","msg":"Diag Get Device Serial 31415926, Soft Serial \n","time":"2020-02-25T16:39:09.98800826Z"}
{"file":"/pillar/pubsub/pubsub.go:154","func":"github.com/lf-edge/eve/pkg/pillar/pubsub.(*PubSub).subscribeImpl","level":"info","msg":"Subscribe(/LedBlinkCounter)\n","time":"2020-02-25T16:39:10.050822323Z"}
{"file":"/pillar/pubsub/pubsub.go:154","func":"github.com/lf-edge/eve/pkg/pillar/pubsub.(*PubSub).subscribeImpl","level":"info","msg":"Subscribe(nim/DeviceNetworkStatus)\n","time":"2020-02-25T16:39:10.051501691Z"}
{"file":"/pillar/pubsub/pubsub.go:154","func":"github.com/lf-edge/eve/pkg/pillar/pubsub.(*PubSub).subscribeImpl","level":"info","msg":"Subscribe(nim/DevicePortConfigList)\n","time":"2020-02-25T16:39:10.052293321Z"}
{"file":"/pillar/cmd/diag/diag.go:1010","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleGlobalConfigModify","level":"info","msg":"handleGlobalConfigModify for global\n","time":"2020-02-25T16:39:10.07230165Z"}
{"file":"/pillar/agentlog/loglevel.go:147","func":"github.com/lf-edge/eve/pkg/pillar/agentlog.HandleGlobalConfig","level":"info","msg":"HandleGlobalConfig(diag, false)\n","time":"2020-02-25T16:39:10.073111891Z"}
{"file":"/pillar/agentlog/loglevel.go:163","func":"github.com/lf-edge/eve/pkg/pillar/agentlog.handleGlobalConfigImpl","level":"info","msg":"HandleGlobalConfig: gcp \u0026{ConfigInterval:60 MetricInterval:60 ResetIfCloudGoneTime:604800 FallbackIfCloudGoneTime:300 MintimeUpdateSuccess:600 StaleConfigTime:600 DownloadGCTime:600 VdiskGCTime:3600 RktGCGracePeriod:3600 DownloadRetryTime:600 DomainBootRetryTime:600 NetworkGeoRedoTime:3600 NetworkGeoRetryTime:600 NetworkTestDuration:30 NetworkTestInterval:300 NetworkTestBetterInterval:0 NetworkFallbackAnyEth:2 NetworkTestTimeout:15 NetworkSendTimeout:120 UsbAccess:true SshAccess:true SshAuthorizedKeys: AllowAppVnc:false AllowNonFreeAppImages:2 AllowNonFreeBaseImages:2 Dom0MinDiskUsagePercent:20 IgnoreDiskCheckForApps:false DefaultLogLevel:info DefaultRemoteLogLevel:info AgentSettings:map[]}\n","time":"2020-02-25T16:39:10.074407116Z"}
{"file":"/pillar/agentlog/loglevel.go:173","func":"github.com/lf-edge/eve/pkg/pillar/agentlog.handleGlobalConfigImpl","level":"info","msg":"handleGlobalConfigModify: level info\n","time":"2020-02-25T16:39:10.075369744Z"}
{"file":"/pillar/cmd/diag/diag.go:1017","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleGlobalConfigModify","level":"info","msg":"handleGlobalConfigModify done for global\n","time":"2020-02-25T16:39:10.076036363Z"}
{"file":"/pillar/pubsub/socketdriver/subscribe.go:219","func":"github.com/lf-edge/eve/pkg/pillar/pubsub/socketdriver.(*Subscriber).translate","level":"info","msg":"Received restart \u003cdone\u003e\n","time":"2020-02-25T16:39:10.077066315Z"}
{"file":"/pillar/watch/watchconfigstatus.go:177","func":"github.com/lf-edge/eve/pkg/pillar/watch.watchReadDir","level":"info","msg":"watchReadDir modified ledconfig.json","time":"2020-02-25T16:39:10.07803824Z"}
{"file":"/pillar/cmd/diag/diag.go:298","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleLedBlinkModify","level":"info","msg":"counter 1 usableAddr 0, derived 1\n","time":"2020-02-25T16:39:10.078975583Z"}
{"file":"/pillar/watch/watchconfigstatus.go:177","func":"github.com/lf-edge/eve/pkg/pillar/watch.watchReadDir","level":"info","msg":"watchReadDir modified global.json","time":"2020-02-25T16:39:10.092277976Z"}
{"file":"/pillar/watch/watchconfigstatus.go:182","func":"github.com/lf-edge/eve/pkg/pillar/watch.watchReadDir","level":"info","msg":"watchReadDir done for /persist/status/nim/DevicePortConfigList\n","time":"2020-02-25T16:39:10.097732418Z"}
{"file":"/pillar/pubsub/socketdriver/subscribe.go:219","func":"github.com/lf-edge/eve/pkg/pillar/pubsub/socketdriver.(*Subscriber).translate","level":"info","msg":"Received restart \u003cdone\u003e\n","time":"2020-02-25T16:39:10.099842145Z"}
{"file":"/pillar/cmd/diag/diag.go:375","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleDPCModify","level":"info","msg":"handleDPCModify for global\n","time":"2020-02-25T16:39:10.111523372Z"}
{"file":"/pillar/watch/watchconfigstatus.go:182","func":"github.com/lf-edge/eve/pkg/pillar/watch.watchReadDir","level":"info","msg":"watchReadDir done for /var/tmp/zededa//LedBlinkCounter\n","time":"2020-02-25T16:39:10.094611088Z"}
{"file":"/pillar/cmd/diag/diag.go:379","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleDPCModify","level":"info","msg":"handleDPCModify: changed   interface{}(\n- \t\u0026types.DevicePortConfigList{},\n+ \ttypes.DevicePortConfigList{\n+ \t\tPortConfigList: []types.DevicePortConfig{\n+ \t\t\t{\n+ \t\t\t\tVersion:      1,\n+ \t\t\t\tKey:          \"lastresort\",\n+ \t\t\t\tTimePriority: s\"1970-01-01 00:00:00 +0000 UTC\",\n+ \t\t\t\tLastFailed:   s\"2020-02-25 13:35:49.35685443 +0000 UTC\",\n+ \t\t\t\tLastError:    \"Failed network test: All test attempts to connect to mydomain.com:49167/api/v1/edgedevice/ping failed: [No IP addresses to connect to https://mydomain.com:49167/api/v1/edgedevice/ping using intf eth1 No IP addresses to connect to https://mydomain.com:49167/api/v1/edgedevice/ping using intf eth0]\",\n+ \t\t\t\tPorts: []types.NetworkPortConfig{\n+ \t\t\t\t\t{\n+ \t\t\t\t\t\tIfName:     \"eth0\",\n+ \t\t\t\t\t\tName:       \"eth0\",\n+ \t\t\t\t\t\tIsMgmt:     true,\n+ \t\t\t\t\t\tFree:       true,\n+ \t\t\t\t\t\tDhcpConfig: types.DhcpConfig{Dhcp: 4},\n+ \t\t\t\t\t},\n+ \t\t\t\t\t{\n+ \t\t\t\t\t\tIfName:     \"eth1\",\n+ \t\t\t\t\t\tName:       \"eth1\",\n+ \t\t\t\t\t\tIsMgmt:     true,\n+ \t\t\t\t\t\tFree:       true,\n+ \t\t\t\t\t\tDhcpConfig: types.DhcpConfig{Dhcp: 4},\n+ \t\t\t\t\t},\n+ \t\t\t\t},\n+ \t\t\t},\n+ \t\t},\n+ \t},\n  )\n","time":"2020-02-25T16:39:10.116329085Z"}
{"file":"/pillar/cmd/diag/diag.go:387","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleDPCModify","level":"info","msg":"handleDPCModify done for global\n","time":"2020-02-25T16:39:10.145512525Z"}
{"file":"/pillar/cmd/diag/diag.go:314","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleDNSModify","level":"info","msg":"handleDNSModify for global\n","time":"2020-02-25T16:39:10.147512825Z"}
{"file":"/pillar/cmd/diag/diag.go:319","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleDNSModify","level":"info","msg":"handleDNSModify: changed   interface{}(\n- \t\u0026types.DeviceNetworkStatus{},\n+ \ttypes.DeviceNetworkStatus{\n+ \t\tVersion: 1,\n+ \t\tPorts: []types.NetworkPortStatus{\n+ \t\t\t{\n+ \t\t\t\tIfName: \"eth0\",\n+ \t\t\t\tName:   \"eth0\",\n+ \t\t\t\tIsMgmt: true,\n+ \t\t\t\tFree:   true,\n+ \t\t\t\tNetworkXObjectConfig: types.NetworkXObjectConfig{\n+ \t\t\t\t\tDhcp:       4,\n+ \t\t\t\t\tSubnet:     net.IPNet{IP: s\"192.168.0.0\", Mask: s\"ffffff00\"},\n+ \t\t\t\t\tGateway:    s\"192.168.0.2\",\n+ \t\t\t\t\tDnsServers: []net.IP{s\"192.168.0.3\"},\n+ \t\t\t\t},\n+ \t\t\t\tAddrInfoList: []types.AddrInfo{\n+ \t\t\t\t\t{\n+ \t\t\t\t\t\tAddr: s\"192.168.0.10\",\n+ \t\t\t\t\t\tGeo: ipinfo.IPInfo{\n+ \t\t\t\t\t\t\tIP:      \"77.234.203.244\",\n+ \t\t\t\t\t\t\tCity:    \"Saint Petersburg\",\n+ \t\t\t\t\t\t\tRegion:  \"St.-Petersburg\",\n+ \t\t\t\t\t\t\tCountry: \"RU\",\n+ \t\t\t\t\t\t\tLoc:     \"59.9386,30.3141\",\n+ \t\t\t\t\t\t\tOrg:     \"AS42289 ITMO University\",\n+ \t\t\t\t\t\t\tPostal:  \"190000\",\n+ \t\t\t\t\t\t},\n+ \t\t\t\t\t\tLastGeoTimestamp: s\"2020-02-25 14:33:57.066275773 +0000 UTC\",\n+ \t\t\t\t\t},\n+ \t\t\t\t\t{Addr: s\"fe80::8eed:73b5:339f:696\"},\n+ \t\t\t\t},\n+ \t\t\t},\n+ \t\t\t{\n+ \t\t\t\tIfName: \"eth1\",\n+ \t\t\t\tName:   \"eth1\",\n+ \t\t\t\tIsMgmt: true,\n+ \t\t\t\tFree:   true,\n+ \t\t\t\tNetworkXObjectConfig: types.NetworkXObjectConfig{\n+ \t\t\t\t\tDhcp:       4,\n+ \t\t\t\t\tSubnet:     net.IPNet{IP: s\"192.168.3.0\", Mask: s\"ffffff00\"},\n+ \t\t\t\t\tGateway:    s\"192.168.3.2\",\n+ \t\t\t\t\tDnsServers: []net.IP{s\"192.168.3.3\"},\n+ \t\t\t\t},\n+ \t\t\t\tAddrInfoList: []types.AddrInfo{{Addr: s\"192.168.3.10\"}, {Addr: s\"fe80::aa76:4ac0:3b46:26ce\"}},\n+ \t\t\t},\n+ \t\t},\n+ \t},\n  )\n","time":"2020-02-25T16:39:10.149471589Z"}
{"file":"/pillar/pubsub/socketdriver/subscribe.go:219","func":"github.com/lf-edge/eve/pkg/pillar/pubsub/socketdriver.(*Subscriber).translate","level":"info","msg":"Received restart \u003cdone\u003e\n","time":"2020-02-25T16:39:10.120002861Z"}
{"file":"/pillar/cmd/diag/diag.go:323","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleDNSModify","level":"info","msg":"handleDNSModify 2 usable addresses\n","time":"2020-02-25T16:39:10.150426556Z"}
{"file":"/pillar/cmd/diag/diag.go:329","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleDNSModify","level":"info","msg":"counter 1 usableAddr 2, derived 2\n","time":"2020-02-25T16:39:10.153073121Z"}

INFO: updated diag information at 2020-02-25T16:39:10.160083744Z
ERROR: Summary: Trying to connect to EV Controller
INFO: Using highest priority DevicePortConfig key lastresort
INFO: Have 2 total ports. 2 ports should be connected to EV controller
INFO: Port eth0: for EV Controller without usage-based charging
INFO: eth0: IP address 192.168.0.10 geolocated to {IP:77.234.203.244 Hostname: City:Saint Petersburg Region:St.-Petersburg Country:RU Loc:59.9386,30.3141 Org:AS42289 ITMO University Postal:190000}
INFO: eth0: DNS servers: 192.168.0.3,
INFO: eth0: no http(s) proxy
INFO: eth0: DNS lookup of mydomain.com returned 192.168.244.225
INFO: eth0: mydomain.com:49167/api/v1/edgedevice/ping StatusOK
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:10.314996146Z"}
ERROR: eth0: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:11.346970933Z"}
ERROR: eth0: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:12.38840533Z"}
ERROR: eth0: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:13.443975419Z"}
ERROR: eth0: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:14.479721984Z"}
ERROR: eth0: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:15.515973365Z"}
ERROR: eth0: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth0: Exceeded 5 retries for get config
INFO: Port eth1: for EV Controller without usage-based charging
INFO: eth1: IP address 192.168.3.10 not geolocated
INFO: eth1: DNS servers: 192.168.3.3,
INFO: eth1: no http(s) proxy
INFO: eth1: DNS lookup of mydomain.com returned 192.168.244.225
INFO: eth1: mydomain.com:49167/api/v1/edgedevice/ping StatusOK
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:15.610524732Z"}
ERROR: eth1: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:16.632794421Z"}
ERROR: eth1: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:17.686804019Z"}
ERROR: eth1: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:18.742322078Z"}
ERROR: eth1: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:19.78326072Z"}
ERROR: eth1: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
{"file":"/pillar/zedcloud/send.go:449","func":"github.com/lf-edge/eve/pkg/pillar/zedcloud.SendOnIntf","level":"error","msg":"sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized","time":"2020-02-25T16:39:20.823043046Z"}
ERROR: eth1: get mydomain.com:49167/api/v1/edgedevice/config failed: sendOnIntf to https://mydomain.com:49167/api/v1/edgedevice/config reqlen 0 statuscode 401 Unauthorized
ERROR: eth1: Exceeded 5 retries for get config
WARNING: 0 out of 2 ports specified to have EV controller connectivity passed test
{"file":"/pillar/cmd/diag/diag.go:336","func":"github.com/lf-edge/eve/pkg/pillar/cmd/diag.handleDNSModify","level":"info","msg":"handleDNSModify done for global\n","time":"2020-02-25T16:39:20.852710665Z"}