Re: [PATCH 0/3] improve debug output for EAL flags unit tests

[Bruce Richardson <bruce.richardson@intel.com>]

On Fri, Jan 23, 2026 at 12:08:15PM +0100, David Marchand wrote:
> Hello Bruce,
> 
> On Wed, 21 Jan 2026 at 10:14, David Marchand <david.marchand@redhat.com> wrote:
> >
> > On Tue, 20 Jan 2026 at 12:26, Bruce Richardson
> > <bruce.richardson@intel.com> wrote:
> > >
> > > If issues arise in the EAL flags unit tests they can be trick to debug
> > > due to the lack of debugging output when running recursive instances of
> > > the test binary with different EAL flags. Try to improve this situation
> > > by adding extra debug output for recursive dpdk-test calls in general,
> > > and to some of the EAL flags tests in particular that are proving
> > > problematic.
> > >
> > > NOTE: there are intermittent failures seen in github actions with the
> > > file-prefix EAL unit tests. The problems seem less frequent, or possibly
> > > "gone", with this set applied, but even if it masks the problem, this
> > > set does give us greater visibility to debug if they do re-occur.
> > >
> > > Bruce Richardson (3):
> > >   app/test: add extra logging for recursive calls
> > >   test/eal_flags: add line numbers to error messages
> > >   test/eal_flags: add extra logging for file prefix tests
> > >
> > >  app/test/test.c           |  14 +-
> > >  app/test/test_eal_flags.c | 373 ++++++++++++++++++++++----------------
> > >  2 files changed, 224 insertions(+), 163 deletions(-)
> >
> > Series applied, thanks Bruce for looking into this.
> 
> We got one occurence in the CI.
> https://github.com/DPDK/dpdk/actions/runs/21214407393/job/61031333760
> 
> Here are the logs:
> 
> 2026-01-21T15:18:20.4304709Z  33/125 DPDK:fast-tests /
> eal_flags_vdev_opt_autotest    FAIL            0.92s   (exit status
> 255 or signal 127 SIGinvalid)
> 2026-01-21T15:18:20.4307907Z >>> DPDK_TEST=eal_flags_vdev_opt_autotest
> MALLOC_PERTURB_=42 /home/runner/work/dpdk/dpdk/build/app/dpdk-test -d
> /home/runner/work/dpdk/dpdk/build/drivers
> 2026-01-21T15:18:20.4309736Z ――――――――――――――――――――――――――――――――――――― ✀
> ―――――――――――――――――――――――――――――――――――――
> 2026-01-21T15:18:20.4310450Z EAL: Detected CPU lcores: 4
> 2026-01-21T15:18:20.4310882Z EAL: Detected NUMA nodes: 1
> 2026-01-21T15:18:20.4311249Z EAL: Detected shared linkage of DPDK
> 2026-01-21T15:18:20.4311730Z EAL: Multi-process socket
> /var/run/dpdk/rte/mp_socket
> 2026-01-21T15:18:20.4312208Z EAL: Selected IOVA mode 'PA'
> 2026-01-21T15:18:20.4312639Z APP: HPET is not enabled, using TSC as
> default timer
> 2026-01-21T15:18:20.4313094Z RTE>>eal_flags_vdev_opt_autotest
> 2026-01-21T15:18:20.4314397Z Running binary with
> argv[]:'/home/runner/work/dpdk/dpdk/build/app/dpdk-test'
> '--file-prefix=vdev' '--no-huge' '--vdev' 'eth_dummy'
> '--driver-path=/home/runner/work/dpdk/dpdk/build/drivers'
> 2026-01-21T15:18:20.4315613Z EAL: Detected CPU lcores: 4
> 2026-01-21T15:18:20.4316012Z EAL: Detected NUMA nodes: 1
> 2026-01-21T15:18:20.4316432Z EAL: Detected shared linkage of DPDK
> 2026-01-21T15:18:20.4316872Z EAL: failed to parse device "eth_dummy"
> 2026-01-21T15:18:20.4317298Z EAL: Unable to parse device 'eth_dummy'
> 2026-01-21T15:18:20.4317770Z EAL: Unregistering with invalid input parameter
> 2026-01-21T15:18:20.4318225Z Error with EAL initialization, ret = -1
> 2026-01-21T15:18:20.4319381Z Running binary with
> argv[]:'/home/runner/work/dpdk/dpdk/build/app/dpdk-test'
> '--file-prefix=vdev' '--no-huge' '--vdev' 'net_ring0'
> '--driver-path=/home/runner/work/dpdk/dpdk/build/drivers'
> 2026-01-21T15:18:20.4320519Z EAL: Detected CPU lcores: 4
> 2026-01-21T15:18:20.4320904Z EAL: Detected NUMA nodes: 1
> 2026-01-21T15:18:20.4321312Z EAL: Detected shared linkage of DPDK
> 2026-01-21T15:18:20.4321831Z EAL: Multi-process socket
> /var/run/dpdk/vdev/mp_socket
> 2026-01-21T15:18:20.4322354Z EAL: Selected IOVA mode 'VA'
> 2026-01-21T15:18:20.4322817Z Calling recursive action for test_invalid_vdev_flag
> 2026-01-21T15:18:20.4323483Z Returned from recursive action for
> test_invalid_vdev_flag with 0
> 2026-01-21T15:18:20.4324455Z Cleaning up
> /home/runner/work/dpdk/dpdk/build/app/dpdk-test recursive instance
> 2026-01-21T15:18:20.4325093Z
> /home/runner/work/dpdk/dpdk/build/app/dpdk-test recursive instance
> returning 0
> 2026-01-21T15:18:20.4326091Z Running binary with
> argv[]:'/home/runner/work/dpdk/dpdk/build/app/dpdk-test'
> '--file-prefix=vdev' '--no-huge' '--vdev' 'net_ring0,args=test'
> '--driver-path=/home/runner/work/dpdk/dpdk/build/drivers'
> 2026-01-21T15:18:20.4326783Z EAL: Detected CPU lcores: 4
> 2026-01-21T15:18:20.4327017Z EAL: Detected NUMA nodes: 1
> 2026-01-21T15:18:20.4327252Z EAL: Detected shared linkage of DPDK
> 2026-01-21T15:18:20.4327550Z EAL: Multi-process socket
> /var/run/dpdk/vdev/mp_socket
> 2026-01-21T15:18:20.4327845Z EAL: Selected IOVA mode 'VA'
> 2026-01-21T15:18:20.4328110Z Calling recursive action for test_invalid_vdev_flag
> 2026-01-21T15:18:20.4328475Z Returned from recursive action for
> test_invalid_vdev_flag with 0
> 2026-01-21T15:18:20.4328998Z Cleaning up
> /home/runner/work/dpdk/dpdk/build/app/dpdk-test recursive instance
> 2026-01-21T15:18:20.4329492Z
> /home/runner/work/dpdk/dpdk/build/app/dpdk-test recursive instance
> returning 0
> 2026-01-21T15:18:20.4330341Z Running binary with
> argv[]:'/home/runner/work/dpdk/dpdk/build/app/dpdk-test'
> '--file-prefix=vdev' '--no-huge' '--vdev'
> 'net_ring0,nodeaction=r1:0:CREATE'
> '--driver-path=/home/runner/work/dpdk/dpdk/build/drivers'
> 2026-01-21T15:18:20.4331077Z EAL: Detected CPU lcores: 4
> 2026-01-21T15:18:20.4331303Z EAL: Detected NUMA nodes: 1
> 2026-01-21T15:18:20.4331530Z EAL: Detected shared linkage of DPDK
> 2026-01-21T15:18:20.4331832Z EAL: Multi-process socket
> /var/run/dpdk/vdev/mp_socket
> 2026-01-21T15:18:20.4332134Z EAL: Selected IOVA mode 'VA'

Looks like the secondary process silently crashes here. No indication why
though. :-(

> 2026-01-21T15:18:20.4332468Z Error (line 490) - process did not run ok
> with valid vdev value with valid args
> 2026-01-21T15:18:20.4332815Z Test Failed
> 2026-01-21T15:18:20.4333029Z RTE>>
> 2026-01-21T15:18:20.4333385Z
> ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――
> 2026-01-21T15:18:20.4333623Z
> 
> And:
> 
> 2026-01-21T15:18:22.3440177Z  36/125 DPDK:fast-tests /
> eal_flags_file_prefix_autotest FAIL            0.50s   (exit status
> 255 or signal 127 SIGinvalid)
> 2026-01-21T15:18:22.3442376Z >>>
> DPDK_TEST=eal_flags_file_prefix_autotest MALLOC_PERTURB_=162
> /home/runner/work/dpdk/dpdk/build/app/dpdk-test -d
> /home/runner/work/dpdk/dpdk/build/drivers
> 2026-01-21T15:18:22.3443273Z ――――――――――――――――――――――――――――――――――――― ✀
> ―――――――――――――――――――――――――――――――――――――
> 2026-01-21T15:18:22.3443617Z EAL: Detected CPU lcores: 4
> 2026-01-21T15:18:22.3443875Z EAL: Detected NUMA nodes: 1
> 2026-01-21T15:18:22.3444115Z EAL: Detected shared linkage of DPDK
> 2026-01-21T15:18:22.3444453Z EAL: Multi-process socket
> /var/run/dpdk/rte/mp_socket
> 2026-01-21T15:18:22.3444751Z EAL: Selected IOVA mode 'PA'
> 2026-01-21T15:18:22.3445036Z APP: HPET is not enabled, using TSC as
> default timer
> 2026-01-21T15:18:22.3445333Z RTE>>eal_flags_file_prefix_autotest
> 2026-01-21T15:18:22.3445927Z Hugepage file /dev/hugepages/rtemap_2
> exists, matching prefix rtemap_
> 2026-01-21T15:18:22.3446300Z Hugepage file /dev/hugepages/rtemap_2 is locked
> 2026-01-21T15:18:22.3446599Z Hugepage file /dev/hugepages/rtemap_1 is locked
> 2026-01-21T15:18:22.3446897Z Hugepage file /dev/hugepages/rtemap_0 is locked
> 2026-01-21T15:18:22.3447615Z Running binary with
> argv[]:'/home/runner/work/dpdk/dpdk/build/app/dpdk-test'
> '--proc-type=secondary' '-m' '18' '--file-prefix=memtest'
> '--driver-path=/home/runner/work/dpdk/dpdk/build/drivers'
> 2026-01-21T15:18:22.3448304Z EAL: Detected CPU lcores: 4
> 2026-01-21T15:18:22.3448532Z EAL: Detected NUMA nodes: 1
> 2026-01-21T15:18:22.3448758Z EAL: Detected shared linkage of DPDK
> 2026-01-21T15:18:22.3449106Z EAL: Multi-process socket
> /var/run/dpdk/memtest/mp_socket_59707_2a8a22b91bd
> 2026-01-21T15:18:22.3449778Z EAL: failed to send to
> (/var/run/dpdk/memtest/mp_socket) due to No such file or directory
> 2026-01-21T15:18:22.3450297Z EAL: Fail to send request
> /var/run/dpdk/memtest/mp_socket:bus_vdev_mp
> 2026-01-21T15:18:22.3450673Z VDEV_BUS: vdev_scan(): Failed to request
> vdev from primary
> 2026-01-21T15:18:22.3450972Z EAL: Selected IOVA mode 'PA'
> 2026-01-21T15:18:22.3451326Z EAL: failed to send to
> (/var/run/dpdk/memtest/mp_socket) due to No such file or directory
> 2026-01-21T15:18:22.3451706Z EAL: Cannot send message to primary
> 2026-01-21T15:18:22.3451967Z EAL: error allocating rte services array
> 2026-01-21T15:18:22.3452224Z EAL: rte_service_init() failed
> 2026-01-21T15:18:22.3452473Z Error with EAL initialization, ret = -1
> 2026-01-21T15:18:22.3452809Z Hugepage file /dev/hugepages/rtemap_2
> exists, matching prefix rtemap_
> 2026-01-21T15:18:22.3453173Z Hugepage file /dev/hugepages/rtemap_2 is locked
> 2026-01-21T15:18:22.3453470Z Hugepage file /dev/hugepages/rtemap_1 is locked
> 2026-01-21T15:18:22.3453764Z Hugepage file /dev/hugepages/rtemap_0 is locked
> 2026-01-21T15:18:22.3454168Z Hugepage file /dev/hugepages/rtemap_2
> exists, matching prefix rtemap_
> 2026-01-21T15:18:22.3454524Z Hugepage file /dev/hugepages/rtemap_2 is locked
> 2026-01-21T15:18:22.3454816Z Hugepage file /dev/hugepages/rtemap_1 is locked
> 2026-01-21T15:18:22.3455110Z Hugepage file /dev/hugepages/rtemap_0 is locked
> 2026-01-21T15:18:22.3455938Z Running binary with
> argv[]:'/home/runner/work/dpdk/dpdk/build/app/dpdk-test' '-m' '18'
> '--file-prefix=memtest1'
> '--driver-path=/home/runner/work/dpdk/dpdk/build/drivers'
> 2026-01-21T15:18:22.3456554Z EAL: Detected CPU lcores: 4
> 2026-01-21T15:18:22.3456775Z EAL: Detected NUMA nodes: 1
> 2026-01-21T15:18:22.3457003Z EAL: Detected shared linkage of DPDK
> 2026-01-21T15:18:22.3457319Z EAL: Multi-process socket
> /var/run/dpdk/memtest1/mp_socket
> 2026-01-21T15:18:22.3457625Z EAL: Selected IOVA mode 'PA'
> 2026-01-21T15:18:22.3457959Z Calling recursive action for test_file_prefix
> 2026-01-21T15:18:22.3458291Z Returned from recursive action for
> test_file_prefix with 0
> 2026-01-21T15:18:22.3458715Z Cleaning up
> /home/runner/work/dpdk/dpdk/build/app/dpdk-test recursive instance
> 2026-01-21T15:18:22.3459202Z
> /home/runner/work/dpdk/dpdk/build/app/dpdk-test recursive instance
> returning 0

So process cleanup ok before returning. All hugepage files should be
automatically deleted.

> 2026-01-21T15:18:22.3459656Z Hugepage file /dev/hugepages/rtemap_2
> exists, matching prefix rtemap_
> 2026-01-21T15:18:22.3460017Z Hugepage file /dev/hugepages/rtemap_2 is locked
> 2026-01-21T15:18:22.3460310Z Hugepage file /dev/hugepages/rtemap_1 is locked
> 2026-01-21T15:18:22.3460608Z Hugepage file /dev/hugepages/rtemap_0 is locked
> 2026-01-21T15:18:22.3460975Z Hugepage file /dev/hugepages/rtemap_2
> exists, matching prefix rtemap_
> 2026-01-21T15:18:22.3461339Z Hugepage file /dev/hugepages/rtemap_2 is locked
> 2026-01-21T15:18:22.3461640Z Hugepage file /dev/hugepages/rtemap_1 is locked
> 2026-01-21T15:18:22.3461933Z Hugepage file /dev/hugepages/rtemap_0 is locked
> 2026-01-21T15:18:22.3462316Z Hugepage file
> /dev/hugepages/memtest1map_8 exists, matching prefix memtest1map_
> 2026-01-21T15:18:22.3462788Z Error (line 1396) - hugepage files for
> memtest1 were not deleted!
> 2026-01-21T15:18:22.3463100Z Test Failed
> 2026-01-21T15:18:22.3463268Z RTE>>
> 2026-01-21T15:18:22.3463597Z
> ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――
> 2026-01-21T15:18:22.3463824Z
> 
> For the latter, I suspect that now passing --driver-path exposes some
> driver leak.

Even if there was a leak, I would have thought all files would be unlinked
anyway. I will dig into this, and discuss with Anatoly too, see if he has
suggestions or ideas...

> But strange that it is not systematic...
> 
> --log-level=*:debug could help...
>
Yes. I will have to see if I can reproduce in a GHA run with that flag
added.

/Bruce