4.5. Log Management¶

4.5.1. `rsyslog`¶

The rsyslogd daemon writes syslog messages in various places (considering its configuration in /etc/rsyslog.conf). Messages for the “daemon” facility are usually stored in /var/log/daemon.log (this is the case for buildroot images). However all messages are usually stored in /var/log/syslog (all facilities included), too.

The fast path sends syslog messages that you can look at later to figure out what happened during startup (and runtime). Here is an extract from /var/log/syslog:

fp-rte[3660]: EAL: Master lcore 1 is ready (tid=c4fdc300;cpuset=[1])
fp-rte[3660]: EAL: PCI device 0000:00:04.0 on NUMA socket -1
fp-rte[3660]: EAL:   probe driver: 8086:100e rte_em_pmd
fp-rte[3660]: EAL:   PCI memory mapped at 0x7f22c3c00000
fp-rte[3660]: PMD: eth_em_dev_init(): port_id 0 vendorID=0x8086 deviceID=0x100e
...
fp-rte[3660]: libfpn_shmem: write procfs: File exists
fp-rte[3660]: FPN: fp_mask=0x2 l_mask=0x2 dpvi_mask=0x1 stats_mask=0xd online=0xf
...
fp-rte[3660]: Create a mbuf pool on socket 0, nb_mbufs=16384
fp-rte[3660]: Bus  Device        ID         Port#  RXQ  RXD/Q  TXQ  TXD/Q  Excl  Interface       Driver name
fp-rte[3660]: PCI  0000:00:04.0  8086:100e  0      1    128    1    512    1     N/A             rte_em_pmd
fp-rte[3660]: PCI  0000:00:05.0  8086:100e  1      1    128    1    512    1     N/A             rte_em_pmd
fp-rte[3660]: PCI  0000:00:06.0  8086:100e  2      1    128    1    512    1     N/A             rte_em_pmd
fp-rte[3660]: Initializing port 0... ntxq=1 nrxq=1 [de:ed:01:f0:95:88] txq0=c1 rxq0=c1 PMD: eth_em_tx_queue_setup(): sw_ring=0x7f22acdccc00 hw_ring=0x7f22acdced00 dma_addr=0xaffced00
fp-rte[3660]: PMD: eth_em_rx_queue_setup(): sw_ring=0x7f22acdbc6c0 hw_ring=0x7f22acdbcbc0 dma_addr=0xaffbcbc0
fp-rte[3660]: PMD: eth_em_rx_init(): forcing scatter mode
fp-rte[3660]: PMD: eth_em_start(): <<
fp-rte[3660]: done
fp-rte[3660]: Initializing port 1... ntxq=1 nrxq=1 [de:ed:02:f7:f2:e5] txq0=c1 rxq0=c1 PMD: eth_em_tx_queue_setup(): sw_ring=0x7f22acdaa480 hw_ring=0x7f22acdac580 dma_addr=0xaffac580
fp-rte[3660]: PMD: eth_em_rx_queue_setup(): sw_ring=0x7f22acd99f40 hw_ring=0x7f22acd9a440 dma_addr=0xaff9a440
fp-rte[3660]: PMD: eth_em_rx_init(): forcing scatter mode
fp-rte[3660]: PMD: eth_em_start(): <<
fp-rte[3660]: done
...
fp-rte[3660]: fpn_sdk_init: dedicated configuration polling lcore -1
fp-rte[3660]: fpn_dpvi_shmem_mmap: fpn_dpvi_shmem sizeof=80
fp-rte[3660]: fpn_dpvi_ring_shmem_mmap: fpn_dpvi_ring_shmem size=266496
fp-rte[3660]: fpn_per_lcore_dpvi_shmem_init: lcoreid 1 mbufs=768
kernel: [   57.450256] dpvi: kernel_cpumask_display() dpvi: fp_mask = 0x2
kernel: [   57.450259] dpvi: kernel_cpumask_display() dpvi: dpvi_mask = 0x1
kernel: [   57.450260] dpvi: kernel_cpumask_display() dpvi: l_mask = 0x2
kernel: [   57.450261] dpvi: kernel_cpumask_display() dpvi: online_mask = 0xf
kernel: [   57.450263] dpvi: dpvi_init_ring() dpvi: cpu 0 use Tx queue 0  ring 1
kernel: [   57.450264] dpvi: dpvi_init_ring() dpvi: cpu 1 use Tx queue 0  ring 1
kernel: [   57.450264] dpvi: dpvi_init_ring() dpvi: cpu 2 use Tx queue 0  ring 1
kernel: [   57.450265] dpvi: dpvi_init_ring() dpvi: cpu 3 use Tx queue 0  ring 1
kernel: [   57.451284] dpvi: dpvi_sysctl_running_fastpath() Watching PID 3660
fp-rte[3660]: fpn-sdk init finished
fp-rte[3660]: fp-ovs: using accelerated functions(avx[x] sse4.2[x] sse4.1[x])
fp-rte[3660]: Using fp-shared=0x7f22a0069000 size=20390912 (19M)
...
fp-rte[3660]: fp-ovs: using accelerated functions(avx[x] sse4.2[x] sse4.1[x])
fp-rte[3660]: fp-vswitch module loaded
fp-rte[3660]: Init core 1
fp-rte[3660]: entering main loop on lcore 1 (master)
fp-rte[3660]:  RX -- lcoreid=1 queueid=0 portid=0
fp-rte[3660]:  RX -- lcoreid=1 queueid=0 portid=1
fp-rte[3660]:  RX -- lcoreid=1 queueid=0 portid=2
fp-rte[3660]:  TX -- lcoreid=1 queueid=0 portid=0
fp-rte[3660]:  TX -- lcoreid=1 queueid=0 portid=1
fp-rte[3660]:  TX -- lcoreid=1 queueid=0 portid=2

If you don’t see anything in /var/log/syslog, make sure the rsyslogd daemon is running:

# ps aux | grep syslog
root        83  0.0  0.0 251864  2648 ?        Ssl  13:23   0:00 /usr/sbin/rsyslogd
root       851  0.0  0.0   4676   648 ttyS0    R+   14:32   0:00 grep syslog

If rsyslogd is not running, refer to your distribution documentation on how to get it started.

Note

Refer to the appropriate manpage (e.g.: man rsyslog.conf) for configuration options.

4.5.2. `journalctl`¶

With SystemD, logging is handled by the systemd-journald daemon. It writes its log in a binary format, and one usually uses journalctl to access it.

Use this command to see syslog messages from a given program (providing its path):

# journalctl /usr/bin/fpmd
Dec 10 15:56:44 dut-vm fpmd[11412]: bpf module registered
Dec 10 15:56:44 dut-vm fpmd[11412]: inaddr module registered
Dec 10 15:56:44 dut-vm fpmd[11412]: inroute module registered
...

You can combine it to follow logs from several programs at once. e.g.:

# journalctl /usr/bin/cmgrd /usr/bin/fpmd
...
Dec 10 15:56:44 dut-vm fpmd[11412]: tunnel module registered
Dec 10 15:56:44 dut-vm fpmd[11412]: fpm_netlink_recv: fpn0 found : ifindex 6 status 40
Dec 10 15:56:44 dut-vm cmgrd[11678]: fp-vswitch module loaded
Dec 10 15:56:44 dut-vm cmgrd[11678]: fpm_connect: trying to connect to fpm
Dec 10 15:56:44 dut-vm cmgrd[11678]: fpvs_cm_init_cb: Could not get OVS "ovs_datapath" family info
Dec 10 15:56:44 dut-vm fpmd[11413]: add:cannot set flags in FP ens4-vr0: [-95]
...

Note

Refer to the appropriate manpage (e.g.: man journalctl) for configuration options.

4.5.3. fast path logs¶

If you have an issue when starting the fast path, take a look at the /var/log/fast-path.log file for fast path startup log messages.

For instance (on a normal startup):

# cat /var/log/fast-path.log
Starting Fast Path...
/usr/bin/fp-rte  --huge-dir=/mnt/huge -n 4 -l 5-6,25-26 --socket-mem 438,0 -d librte_pmd_vhost.so -w 0000:05:00.0 -w 0000:05:00.1 -w 0000:05:00.2 -w 0000:05:00.3 -w 0000:83:00.0 -w 0000:83:00.1 --vdev
=pmd-vhost0,sockname=/tmp/pmd-vhost0,rxqmap=auto:rr/nb_ring:1,txqmap=auto:hash/nb_ring:1,loglevel=2 --vdev=pmd-vhost1,sockname=/tmp/pmd-vhost1,rxqmap=auto:rr/nb_ring:1,txqmap=auto:hash/nb_ring:1,loglevel=2
--  -t c5=0:1:2:3:4:5/c6=0:1:2:3:4:5/c25=0:1:2:3:4:5/c26=0:1:2:3:4:5 --nb-mbuf 65536,0 --
Based on DPDK v2.2.0
EAL: Detected lcore 0 as core 0 on socket 0
...
EAL: Detected lcore 39 as core 12 on socket 1
EAL: Support maximum 255 logical core(s) by configuration.
EAL: Detected 40 lcore(s)
EAL: VFIO modules not all loaded, skip VFIO support...
EAL: Setting up physically contiguous memory...
...
EAL: Requesting 219 pages of size 2MB from socket 0
EAL: TSC frequency is ~2992788 KHz
EAL: open shared lib librte_pmd_vhost.so
PMD: PMD virtio vhost, Copyright(c) 2014-2015 6WIND S.A.
EAL: Master lcore 5 is ready (tid=aa486b40;cpuset=[5])
PMD: Initializing 6WIND vhost PMD (pmd-vhost0)
PMD: pmd-vhost[0] pmd_vhost_parse_args_cb(): The loglevel option is deprecated. Please, use the verbose option to enable debug messages
PMD: Initializing 6WIND vhost PMD (pmd-vhost1)
PMD: pmd-vhost[0] pmd_vhost_parse_args_cb(): The loglevel option is deprecated. Please, use the verbose option to enable debug messages
EAL: lcore 25 is ready (tid=8bbe7700;cpuset=[25])
EAL: lcore 6 is ready (tid=8c3e8700;cpuset=[6])
EAL: lcore 26 is ready (tid=8b3e6700;cpuset=[26])
EAL: PCI device 0000:05:00.0 on NUMA socket 0
EAL:   probe driver: 8086:1521 rte_igb_pmd
EAL:   PCI memory mapped at 0x7fb1a9000000
EAL:   PCI memory mapped at 0x7fb1a9020000
PMD: eth_igb_dev_init(): port_id 2 vendorID=0x8086 deviceID=0x1521
...
Using fpn_port 0x7fb1aa327000 size=150576 (0M)
Starting cpuset...
cpuset.sh: creating cpuset system
cpuset.sh: try to move all tasks from cpuset root to system
......................................................................................................................cpuset.sh: moved 596 tasks among 1204
cpuset successfully started
Info: no configuration file /etc/fp-daemons.env for fp-daemons.sh, using defaults
Starting Fast Path Daemons...
Starting Fast Path Manager...
/usr/bin/fpmd
Fast Path Manager successfully started
Starting Hitflags daemon...
/usr/bin/hitflagsd
Hitflags daemon successfully started
Fast Path Daemons successfully started
Fast Path successfully started

4.5.4. `fpmd` logs¶

You can start fpmd with -v option to have more verbose output. To do that, either:

kill and restart (providing -v) the fpmd process, once the fast path has been started:
```
# killall fpmd
# fpmd -v
```
provide -v in FPM_OPTIONS when starting the fast path (you could set it in /etc/fpm.env too):
```
# FPM_OPTIONS='-v' fast-path.sh start
```

4.5.5. `cmgrd` logs¶

When facing a synchronization issue, check first the line with fpm_connection in the log. It should display connected to fpm socket when the connection is established between cmgrd and fpmd.

You can start cmgrd with -d option (use 0xffffffff for maximum debug level) to display more information regarding received netlink messages, messages sent to fpmd, etc. To do that, either:

kill and restart (providing -d) the cmgrd process, once the Linux - Fast Path Synchronization has been started:
```
# killall cmgrd
# cmgrd -d 0xffffffff
```
provide -d in CMGR_OPTIONS when starting the Linux - Fast Path Synchronization (you could set it in /etc/cmgr.env too):
```
# CMGR_OPTIONS='-d 0xffffffff' linux-fp-sync.sh start
```

4.5.6. OpenStack logs¶

When you have an issue regarding VM spawning, take a look at /var/log/nova/nova-compute.log on the compute node hosting the VM.

In particular, look for messages with error or trace in it. For instance:

# grep -iE "(error|trace)" /var/log/nova/nova-compute.log
2016-01-27 11:37:22.286 12945 ERROR nova.network.linux_net [req-b7fdc659-2fd5-4d9e-942c-803f71c2cce1 d82509fae77e41009880defd0bbd829e d9c0a5bd157947bab06d355bf4772db7 - - -] \
  Unable to execute ['ovs-vsctl', '--timeout=120', '--', '--if-exists', 'del-port', u'tap13d2cb29-d6', '--', 'add-port', 'br-int', u'tap13d2cb29-d6', '--', 'set', 'Interface', \
                     u'tap13d2cb29-d6', u'external-ids:iface-id=13d2cb29-d61c-46d9-afe9-98b6aa0a43ea', 'external-ids:iface-status=active', u'external-ids:attached-mac=fa:16:3e:6d:ac:ea', \
                     'external-ids:vm-uuid=1065e38c-e6c6-423f-8140-5d0c021d3af0']. Exception: Unexpected error while running command.
2016-01-27 11:37:22.289 12945 ERROR nova.compute.manager [req-b7fdc659-2fd5-4d9e-942c-803f71c2cce1 d82509fae77e41009880defd0bbd829e d9c0a5bd157947bab06d355bf4772db7 - - -] \
  [instance: 1065e38c-e6c6-423f-8140-5d0c021d3af0] Instance failed to spawn
2016-01-27 11:37:22.289 12945 ERROR nova.compute.manager [instance: 1065e38c-e6c6-423f-8140-5d0c021d3af0] AgentError: Error during following call to agent: \
  ['ovs-vsctl', '--timeout=120', '--', '--if-exists', 'del-port', u'tap13d2cb29-d6', '--', 'add-port', 'br-int', u'tap13d2cb29-d6', '--', 'set', 'Interface', u'tap13d2cb29-d6', \
   u'external-ids:iface-id=13d2cb29-d61c-46d9-afe9-98b6aa0a43ea', 'external-ids:iface-status=active', u'external-ids:attached-mac=fa:16:3e:6d:ac:ea', \
   'external-ids:vm-uuid=1065e38c-e6c6-423f-8140-5d0c021d3af0']
2016-01-27 11:37:22.289 12945 ERROR nova.compute.manager [instance: 1065e38c-e6c6-423f-8140-5d0c021d3af0]

There are interesting files regarding running instances available on the compute nodes, in /var/lib/nova/instances:

# tree /var/lib/nova/instances
/var/lib/nova/instances
|-- 54fff47b-fa5e-4401-8309-e2da66c01d66
|   |-- console.log
|   |-- disk
|   |-- disk.info
|   +-- libvirt.xml
|-- 7fb5ce27-cb7a-4a3b-94d8-afb84ddd3c5b
|   |-- console.log
|   |-- disk
|   |-- disk.info
|   +-- libvirt.xml
|-- _base
|   +-- 775fa67e40ab15538f2f01969e50a38078c09e9b
|-- compute_nodes
+-- locks
    |-- nova-775fa67e40ab15538f2f01969e50a38078c09e9b
    +-- nova-storage-registry-lock

For instance, you can find the libvirt domain file used to boot the VM:

# head /var/lib/nova/instances/54fff47b-fa5e-4401-8309-e2da66c01d66/libvirt.xml
<domain type="kvm">
  <uuid>54fff47b-fa5e-4401-8309-e2da66c01d66</uuid>
  <name>instance-00000003</name>
  <memory>524288</memory>
  <memoryBacking>
    <hugepages>
      <page size="2048" nodeset="0" unit="KiB"/>
    </hugepages>
  </memoryBacking>
  <numatune>

Or you can look at a currently running Nova instance console logs:

# tail /var/lib/nova/instances/54fff47b-fa5e-4401-8309-e2da66c01d66/console.log
ec2: #############################################################
-----BEGIN SSH HOST KEY KEYS-----
ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYT[...]Osfj0fFcxJvE2Roc= root@compute1-vm
ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQ[...]JUYLnAaNV8oNz1AId root@compute1-vm
-----END SSH HOST KEY KEYS-----
Cloud-init v. 0.7.5 finished at Wed, 27 Jan 2016 12:37:49 +0000. Datasource DataSourceEc2.
Up 18.67 seconds

Ubuntu 14.04.2 LTS vm1-compute1-vm-ubuntu-14 ttyS0

Note

For console logs, however, we recommend using nova console-log <ID> on the controller node, for a similar result.
You may also access your VM console itself by accessing horizon (which must be installed and started obviously).

From the administration panel, access Compute > Instances > [your instance] > Console:

If you want Nova to provide you with more information when running, you can configure the verbose and debug options to True in /etc/nova/nova.conf:

# grep -iE "(verbose|debug)" /etc/nova/nova.conf
verbose = True
debug = True

Once configured, restart the nova-compute service.

On Ubuntu Server:
```
# service nova-compute restart
```

On Red Hat 7:

# systemctl restart openstack-nova-compute.service

Similarly, if you want Neutron to provide you with more information, configure verbose and debug options in /etc/neutron/neutron.conf:

# grep -iE "(verbose|debug)" /etc/neutron/neutron.conf
verbose = True
debug = True

Once configured, restart the Neutron service.

Note

Do not keep verbose and debug options set on production environments, as it is very, very talkative. It makes researching interesting information in the log difficult.

4.5. Log Management¶

4.5.1. rsyslog¶

4.5.2. journalctl¶

4.5.3. fast path logs¶

4.5.4. fpmd logs¶

4.5.5. cmgrd logs¶

4.5.6. OpenStack logs¶

4.5.1. `rsyslog`¶

4.5.2. `journalctl`¶

4.5.4. `fpmd` logs¶

4.5.5. `cmgrd` logs¶