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
) thefpmd
process, once the fast path has been started:# killall fpmd # fpmd -v
provide
-v
inFPM_OPTIONS
when starting the fast path (you could set it in/etc/fpm.env
too):# FPM_OPTIONS='-v' fast-path.sh start
See also
Linux - Fast Path Synchronization
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
) thecmgrd
process, once the Linux - Fast Path Synchronization has been started:# killall cmgrd # cmgrd -d 0xffffffff
provide
-d
inCMGR_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
See also
Linux - Fast Path Synchronization
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.