log

Host: Linux dyser 4.14.46 x86_64 AMD Ryzen 5 1600 Six-Core Processor
Image: eugeneia/snabb-nfv-test
Pull Request: #1361
Target Head: b9da7caa1928256a3b490867e9bc62dfbcd21ede
Pull Request Head: e22e6832de914ccc13bff172e0d47dc2e3cd55a3
SNABB_PCI_INTEL1G0=0000:22:00.0 Ethernet controller: Intel Corporation I350 Gigabit Network Connection (rev 01)
SNABB_PCI_INTEL1G1=0000:23:00.0 Ethernet controller: Intel Corporation I350 Gigabit Network Connection (rev 01)

Checking for performance regressions:

Checking test suite:
TEST      core.app
TEST      core.memory
TEST      core.main
TEST      core.worker
TEST      core.packet
TEST      core.timer
TEST      core.link
TEST      core.counter
TEST      core.histogram
TEST      core.shm
TEST      core.lib
TEST      apps.bridge.mac_table
TEST      apps.intel.intel_app
SKIPPED   testlog/apps.intel.intel_app
TEST      apps.keyed_ipv6_tunnel.tunnel
TEST      apps.tap.tap
SKIPPED   testlog/apps.tap.tap
TEST      apps.pcap.tap
TEST      apps.test.synth
TEST      apps.test.match
TEST      apps.rss.rss
TEST      apps.packet_filter.pcap_filter
TEST      apps.lwaftr.V4V6
TEST      apps.lwaftr.ctable_wrapper
TEST      apps.lwaftr.binding_table
TEST      apps.lwaftr.rangemap
TEST      apps.lwaftr.nh_fwd
TEST      apps.lwaftr.ndp
TEST      apps.lwaftr.lwdebug
TEST      apps.socket.unix
TEST      apps.socket.raw
ERROR     testlog/apps.socket.raw

ERROR during tests:
src/testlog/apps.bridge.mac_table:
Jun 25 2018 13:38:51 mac_table: resizing from 512 to 2048 hash buckets, new target size 1024 (590 MAC entries, old target size 256, size/bucket overflow: true/true)

src/testlog/apps.intel.intel_app:
selftest: intel_app
SNABB_PCI_INTEL[0|1] not set or not suitable.
EXITCODE: 43

src/testlog/apps.keyed_ipv6_tunnel.tunnel:
Keyed IPv6 tunnel selftest
link report:
                 102 sent on comparator.output -> match.comparator (loss rate: 0%)
                 102 sent on source.output -> tunnel.decapsulated (loss rate: 0%)
                 102 sent on tunnel.decapsulated -> match.rx (loss rate: 0%)
                 102 sent on tunnel.encapsulated -> tunnel.encapsulated (loss rate: 0%)
apps report:
match
run simple one second benchmark ...
selftest passed

src/testlog/apps.lwaftr.binding_table:
selftest: binding_table
ok

src/testlog/apps.lwaftr.ctable_wrapper:
selftest: apps.lwaftr.ctable_wrapper
selftest: ok

src/testlog/apps.lwaftr.lwdebug:

src/testlog/apps.lwaftr.ndp:
selftest: ndp
NDP: Resolving '2001:db8::2'
NDP: Resolving '2001:db8::1'
NDP: '2001:db8::2' resolved (16:98:2b:a0:94:81)
NDP: '2001:db8::1' resolved (da:43:9d:88:a4:1f)
selftest: ok

src/testlog/apps.lwaftr.nh_fwd:
nh_fwd: selftest
nh_fwd4: cache_refresh_interval set to 0 seconds
nh_fwd4: cache_refresh_interval set to 0 seconds
load: time: 0.10s  fps: 19        fpGbps: 0.000 fpb: 0   bpp: 57   sleep: 100 us
nh_fwd4: cache_refresh_interval set to 0 seconds
nh_fwd4: static next_hop_mac 52:54:00:00:00:02
load: time: 0.10s  fps: 9         fpGbps: 0.000 fpb: 0   bpp: 72   sleep: 100 us
nh_fwd4: cache_refresh_interval set to 0 seconds
load: time: 0.10s  fps: 9         fpGbps: 0.000 fpb: 0   bpp: 72   sleep: 100 us
nh_fwd6: cache_refresh_interval set to 0 seconds
load: time: 0.10s  fps: 19        fpGbps: 0.000 fpb: 0   bpp: 86   sleep: 100 us
nh_fwd6: cache_refresh_interval set to 0 seconds
load: time: 0.10s  fps: 19        fpGbps: 0.000 fpb: 0   bpp: 86   sleep: 100 us
nh_fwd6: cache_refresh_interval set to 0 seconds
nh_fwd6: static next_hop_mac 52:54:00:00:00:02
load: time: 0.10s  fps: 9         fpGbps: 0.000 fpb: 0   bpp: 86   sleep: 100 us
nh_fwd6: cache_refresh_interval set to 0 seconds
load: time: 0.10s  fps: 9         fpGbps: 0.000 fpb: 0   bpp: 86   sleep: 100 us

src/testlog/apps.lwaftr.rangemap:
No PMU available: single core cpu affinity required
lookup: 3.57 ns per iteration (result: 0)

src/testlog/apps.lwaftr.V4V6:
V4V6: selftest
load: time: 0.10s  fps: 29        fpGbps: 0.000 fpb: 0   bpp: 71   sleep: 100 us
OK

src/testlog/apps.packet_filter.pcap_filter:
selftest: pcap_filter
Run for 1 second (stateful = false)...
link report:
             546,801 sent on pcap_filter.output -> sink.input (loss rate: 0%)
          14,672,496 sent on repeater.output -> pcap_filter.input (loss rate: 0%)
                 161 sent on source.output -> repeater.input (loss rate: 0%)
ok: accepted 3.7267% of inputs (within tolerance)
Run for 1 second (stateful = true)...
link report:
             645,785 sent on pcap_filter.output -> sink.input (loss rate: 0%)
           8,664,288 sent on repeater.output -> pcap_filter.input (loss rate: 0%)
                 161 sent on source.output -> repeater.input (loss rate: 0%)
ok: accepted 7.4534% of inputs (within tolerance)
Run for 1 second (stateful = false)...
link report:
             453,453 sent on pcap_filter.output -> sink.input (loss rate: 0%)
          12,167,682 sent on repeater.output -> pcap_filter.input (loss rate: 0%)
                 161 sent on source.output -> repeater.input (loss rate: 0%)
ok: accepted 3.7267% of inputs (within tolerance)
Run for 1 second (stateful = true)...
link report:
             462,329 sent on pcap_filter.output -> sink.input (loss rate: 0%)
           6,202,926 sent on repeater.output -> pcap_filter.input (loss rate: 0%)
                 161 sent on source.output -> repeater.input (loss rate: 0%)
ok: accepted 7.4534% of inputs (within tolerance)
selftest: ok

src/testlog/apps.pcap.tap:
selftest: apps.pcap.tap
selftest: ok

src/testlog/apps.rss.rss:
link report:
             359,464 sent on rss.default_1 -> sink11.input (loss rate: 0%)
             359,522 sent on rss.default_2 -> sink12.input (loss rate: 0%)
             359,896 sent on rss.default_3 -> sink13.input (loss rate: 0%)
             360,338 sent on rss.default_4 -> sink14.input (loss rate: 0%)
             179,933 sent on rss.ip6_1 -> sink31.input (loss rate: 0%)
             179,500 sent on rss.ip6_2 -> sink32.input (loss rate: 0%)
             180,829 sent on rss.ip6_3 -> sink33.input (loss rate: 0%)
             180,083 sent on rss.ip6_4 -> sink34.input (loss rate: 0%)
             179,509 sent on rss.ip_1 -> sink21.input (loss rate: 0%)
             179,439 sent on rss.ip_2 -> sink22.input (loss rate: 0%)
             179,963 sent on rss.ip_3 -> sink23.input (loss rate: 0%)
             179,964 sent on rss.ip_4 -> sink24.input (loss rate: 0%)
             719,610 sent on source1.output -> rss.input_plain (loss rate: 0%)
             719,610 sent on source2.output -> vlan.input (loss rate: 0%)
             719,610 sent on vlan.output -> rss.input_vlan (loss rate: 0%)

src/testlog/apps.socket.raw:
link report:
                   1 sent on lo.tx -> match.rx (loss rate: 0%)
apps report:
match
Not matched:
02 00 00 00 00 02 02 00 00 00 00 01 86 DD 60 00 00 00 00 00 3B 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01
core/main.lua:26: assertion failed!

Stack Traceback
===============
(1) Lua function 'handler' at file 'core/main.lua:168' (best guess)
	Local variables:
	 reason = string: "core/main.lua:26: assertion failed!"
	 (*temporary) = C function: print
(2) global C function 'error'
(3) Lua global 'assert' at file 'core/main.lua:26'
	Local variables:
	 v = boolean: false
(4) Lua field 'selftest' at file 'apps/socket/raw.lua:158'
	Local variables:
	 datagram = table: 0x41838608  {packet:function: 0x41838b90, _freelist:table: 0x41838630, pop_raw:function: 0x418388b8 (more...)}
	 ethernet = table: 0x402251d8  {pton:function: 0x41825ea8, new:function: 0x41825ce0, src_eq:function: 0x418261c0 (more...)}
	 ipv6 = table: 0x40229bd0  {pton:function: 0x402252c0, version:function: 0x402253f8, new:function: 0x40225088 (more...)}
	 Match = table: 0x4183a268  {report:function: 0x4183a340, new:function: 0x4183a378, push:function: 0x4183a398 (more...)}
	 c = table: 0x4183a420  {links:table: 0x4183a618, apps:table: 0x4183a160}
	 dg_tx = table: 0x41bc49e8  {_offset:0, _push:table: 0x40ed5f58, _recycled:false, _instance:true, _packet:cdata<struct packet *[1]>: 0x40ed6338 (more...)}
(5) Lua function 'opt' at file 'program/snsh/snsh.lua:31' (best guess)
	Local variables:
	 arg = string: "apps.socket.raw"
(6) Lua field 'dogetopt' at file 'core/lib.lua:426'
	Local variables:
	 args = table: 0x4182af00  {1:-t, 2:apps.socket.raw}
	 actions = table: 0x40fc7e28  {t:function: 0x40fc3c70, q:function: 0x40fc3cf8, P:function: 0x40fc7120 (more...)}
	 opts = string: "hl:p:t:die:j:P:q:"
	 long_opts = table: 0x40fc8aa0  {jit:j, help:h, program:p, test:t, load:l, package-path:P, debug:d, sigquit:q (more...)}
	 opts = table: 0x40fc3cb0  {1:t}
	 optind = number: 3
	 optarg = table: 0x40223ad0  {1:apps.socket.raw}
	 (for generator) = C function: builtin#6
	 (for state) = table: 0x40fc3cb0  {1:t}
	 (for control) = number: 1
	 i = number: 1
	 v = string: "t"
(7) Lua field 'run' at file 'program/snsh/snsh.lua:65'
	Local variables:
	 parameters = table: 0x4182af00  {1:-t, 2:apps.socket.raw}
	 profiling = boolean: false
	 traceprofiling = boolean: false
	 start_repl = boolean: false
	 noop = boolean: true
	 program = nil
	 opt = table: 0x40fc7e28  {t:function: 0x40fc3c70, q:function: 0x40fc3cf8, P:function: 0x40fc7120 (more...)}
(8) Lua function 'main' at file 'core/main.lua:67' (best guess)
	Local variables:
	 program = string: "snsh"
	 args = table: 0x4182af00  {1:-t, 2:apps.socket.raw}
(9) global C function 'xpcall'
(10) main chunk of file 'core/main.lua' at line 238
(11)  C function 'require'
(12) global C function 'pcall'
(13) main chunk of file 'core/startup.lua' at line 3
(14) global C function 'require'
(15) main chunk of [string "require "core.startup""] at line 1
	nil
EXITCODE: 1

src/testlog/apps.socket.unix:
selftest: socket/unix
link report:
               1,476 sent on client.tx -> check_client_tx.rx (loss rate: 0%)
             150,756 sent on say_hello.tx -> client.rx (loss rate: 0%)
               1,477 sent on server.tx -> server.rx (loss rate: 0%)
selftest: done

src/testlog/apps.tap.tap:
EXITCODE: 43

src/testlog/apps.test.match:
load: time: 0.01s  fps: 42,655    fpGbps: 0.019 fpb: 307 bpp: 8    sleep: 0   us
load: time: 0.00s  fps: 65,314    fpGbps: 0.029 fpb: 104 bpp: 8    sleep: 0   us
load: time: 0.00s  fps: 124,446   fpGbps: 0.055 fpb: 308 bpp: 9    sleep: 0   us

src/testlog/apps.test.synth:
link report:
                   6 sent on reader.output -> match.comparator (loss rate: 0%)
                 102 sent on synth.output -> match.rx (loss rate: 0%)
apps report:
match

src/testlog/core.app:
Restarting app2 (died at 9964.485976: core/app.lua:704: Push error.)
Restarting app1 (died at 9964.485976: core/app.lua:698: Pull error.)
Restarting app2 (died at 9966.485995: core/app.lua:704: Push error.)
Restarting app1 (died at 9966.485995: core/app.lua:698: Pull error.)
Restarting app3 (died at 9968.486032: core/app.lua:710: Report error.)
Restarting app2 (died at 9968.486142: core/app.lua:704: Push error.)
Restarting app1 (died at 9968.486142: core/app.lua:698: Pull error.)
selftest: app
empty -> c1
c1 -> c1
c1 -> c2
c2 -> c1
c1 -> empty
c_fail
apps report:
app3
app2	[dead: core/app.lua:704: Push error.]
app1	[dead: core/app.lua:698: Pull error.]
apps report:
app3
app2	[dead: core/app.lua:704: Push error.]
app1	[dead: core/app.lua:698: Pull error.]

src/testlog/core.counter:
selftest: core.counter
selftest ok

src/testlog/core.histogram:
selftest: histogram
selftest ok

src/testlog/core.lib:
selftest: lib
Testing equal
Testing load_string
Testing load/store_conf
Testing csum
Testing hex(un)dump
Testing ntohl
Testing parse

src/testlog/core.link:
selftest: link
selftest OK

src/testlog/core.main:
selftest

src/testlog/core.memory:
selftest: memory
Kernel vm.nr_hugepages: 81
[mounting /var/run/snabb/hugetlbfs]
  Allocating a 2MB HugeTLB:Got 2MB
    Physical address: 0x0001a5a00000
    Virtual address:  0x5001a5a00000
  Allocating a 2MB HugeTLB:Got 2MB
    Physical address: 0x0001b7e00000
    Virtual address:  0x5001b7e00000
  Allocating a 2MB HugeTLB:Got 2MB
    Physical address: 0x0001a6a00000
    Virtual address:  0x5001a6a00000
  Allocating a 2MB HugeTLB:Got 2MB
    Physical address: 0x000191800000
    Virtual address:  0x500191800000
Kernel vm.nr_hugepages: 81
Testing automatic remapping of DMA memory
    Unmapping cdata<char *>: 0x5001a5a00000
    Unmapping cdata<char *>: 0x5001b7e00000
    Unmapping cdata<char *>: 0x5001a6a00000
    Unmapping cdata<char *>: 0x500191800000
    Writing   cdata<char *>: 0x5001a5a00000
    Writing   cdata<char *>: 0x5001b7e00000
    Writing   cdata<char *>: 0x5001a6a00000
    Writing   cdata<char *>: 0x500191800000
Created 4 on-demand memory mappings with SIGSEGV handler.
HugeTLB page allocation OK.

src/testlog/core.packet:

src/testlog/core.shm:
selftest: shm
checking resolve..
checking shared memory..
create shm/selftest/obj
checking exists..
checking many objects..
10000 objects created
10000 objects unmapped
selftest ok

src/testlog/core.timer:
selftest: timer
ok (973,855 callbacks in 0.1697 seconds)

src/testlog/core.worker:
selftest: worker
Starting children
Worker status:
  worker w3: pid=92 alive=true
  worker w1: pid=90 alive=true
  worker w2: pid=91 alive=true
Stopping children
Worker status:
  worker w3: pid=92 alive=false
  worker w1: pid=90 alive=false
  worker w2: pid=91 alive=false
selftest: done