Bug 1734327 - test_gdb fails with Unable to read information on python frame
Summary: test_gdb fails with Unable to read information on python frame
Keywords:
Status: CLOSED WORKSFORME
Alias: None
Product: Fedora
Classification: Fedora
Component: python3
Version: 32
Hardware: Unspecified
OS: Unspecified
low
low
Target Milestone: ---
Assignee: Petr Viktorin (pviktori)
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: 1678277
TreeView+ depends on / blocked
 
Reported: 2019-07-30 09:09 UTC by Miro Hrončok
Modified: 2020-03-27 13:53 UTC (History)
13 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-03-27 13:53:10 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Python 38350 0 None None None 2019-10-02 16:38:33 UTC

Description Miro Hrončok 2019-07-30 09:09:42 UTC
With Python 3.8.0b3, we get this failures:

======================================================================
FAIL: test_pyup_command (test.test_gdb.StackNavigationTests)
Verify that the "py-up" command works
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 710, in test_pyup_command
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 272, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\n#5 Frame 0x7fffea7a18c0, for file /builddir/build/BUILD/Python-3.8.0b3/Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))\n    id(42)\n' did not match '^.*\n#[0-9]+ Frame 0x-?[0-9a-f]+, for file .*gdb_sample.py, line 7, in bar \\(a=1, b=2, c=3\\)\n    baz\\(a, b, c\\)\n$'
======================================================================
FAIL: test_up_at_top (test.test_gdb.StackNavigationTests)
Verify handling of "py-up" at the top of the stack
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 729, in test_up_at_top
    self.assertEndsWith(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 266, in assertEndsWith
    self.assertTrue(actual.endswith(exp_end),
AssertionError: False is not true : 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\n#5 Frame 0x7fffea7a18c0, for file /builddir/build/BUILD/Python-3.8.0b3/Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))\n    id(42)\n#10 Frame 0x7fffea739220, for file /builddir/build/BUILD/Python-3.8.0b3/Lib/test/gdb_sample.py, line 7, in bar (a=1, b=2, c=3)\n    baz(a, b, c)\n#14 Frame 0x7fffea82e790, for file /builddir/build/BUILD/Python-3.8.0b3/Lib/test/gdb_sample.py, line 4, in foo (a=1, b=2, c=3)\n    bar(a, b, c)\n#18 Frame 0x7fffea79b650, for file /builddir/build/BUILD/Python-3.8.0b3/Lib/test/gdb_sample.py, line 12, in <module> ()\n    foo(1, 2, 3)\n' did not end with 'Unable to find an older python frame\n'
======================================================================
FAIL: test_up_then_down (test.test_gdb.StackNavigationTests)
Verify "py-up" followed by "py-down"
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 739, in test_up_then_down
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 272, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\n#5 Frame 0x7fffea7a18c0, for file /builddir/build/BUILD/Python-3.8.0b3/Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))\n    id(42)\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\n' did not match '^.*\n#[0-9]+ Frame 0x-?[0-9a-f]+, for file .*gdb_sample.py, line 7, in bar \\(a=1, b=2, c=3\\)\n    baz\\(a, b, c\\)\n#[0-9]+ Frame 0x-?[0-9a-f]+, for file .*gdb_sample.py, line 10, in baz \\(args=\\(1, 2, 3\\)\\)\n    id\\(42\\)\n$'
======================================================================
FAIL: test_basic_command (test.test_gdb.PyPrintTests)
Verify that the "py-print" command works
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 917, in test_basic_command
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 272, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\nUnable to read information on python frame\n' did not match ".*\\nlocal 'args' = \\(1, 2, 3\\)\\n.*"
======================================================================
FAIL: test_print_after_up (test.test_gdb.PyPrintTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 926, in test_print_after_up
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 272, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\n#5 Frame 0x7fffea7a18c0, for file /builddir/build/BUILD/Python-3.8.0b3/Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))\n    id(42)\n\'c\' not found\n\'b\' not found\n\'a\' not found\n' did not match ".*\\nlocal 'c' = 3\\nlocal 'b' = 2\\nlocal 'a' = 1\\n.*"
======================================================================
FAIL: test_printing_builtin (test.test_gdb.PyPrintTests)
----------------------------------------------------------------------
Traceback (most recent call last):
BUILDSTDERR:   File "/builddir/Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "time_gmtime" not defined.
BUILDSTDERR: Function "time_gmtime" not defined.
BUILDSTDERR: Function "builtin_len" not defined.
BUILDSTDERR: Function "builtin_len" not defined.
BUILDSTDERR: Function "builtin_locals" not defined.
BUILDSTDERR: Function "builtin_locals" not defined.
BUILDSTDERR: Function "builtin_iter" not defined.
BUILDSTDERR: Function "builtin_iter" not defined.
BUILDSTDERR: Function "builtin_sorted" not defined.
BUILDSTDERR: Function "builtin_sorted" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: Function "builtin_id" not defined.
BUILDSTDERR: test test_gdb failed
build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 942, in test_printing_builtin
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 272, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\nUnable to read information on python frame\n' did not match ".*\\nbuiltin 'len' = <built-in method len of module object at remote 0x-?[0-9a-f]+>\\n.*"
======================================================================
FAIL: test_printing_global (test.test_gdb.PyPrintTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 934, in test_printing_global
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 272, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\nUnable to read information on python frame\n' did not match ".*\\nglobal '__name__' = '__main__'\\n.*"
======================================================================
FAIL: test_basic_command (test.test_gdb.PyLocalsTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 951, in test_basic_command
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 272, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\nUnable to read information on python frame\n' did not match '.*\\nargs = \\(1, 2, 3\\)\\n.*'
======================================================================
FAIL: test_locals_after_up (test.test_gdb.PyLocalsTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 960, in test_locals_after_up
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.0b3/Lib/test/test_gdb.py", line 272, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib64/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b3/Python/bltinmodule.c:1172\n1172\t    PyObject *id = PyLong_FromVoidPtr(v);\n#2 <built-in method id of module object at remote 0x7fffea80ef50>\n#5 Frame 0x7fffea7a18c0, for file /builddir/build/BUILD/Python-3.8.0b3/Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))\n    id(42)\nargs = (1, 2, 3)\n' did not match '.*\\na = 1\\nb = 2\\nc = 3\\n.*'
----------------------------------------------------------------------

Comment 1 Charalampos Stratakis 2019-07-30 09:28:54 UTC
Is this on the debug build?

Comment 2 Miro Hrončok 2019-07-30 09:30:14 UTC
Oh, sorry for not mentioning that. Yes, this is on the debug build. AFAIK test_gdb only runs there.

(The python38 package has the debug build turned off by default.)

Comment 3 Charalampos Stratakis 2019-07-30 09:50:04 UTC
Then it could be this upstream issue that's causing it (aka a side effect of the extension flags reduction change): https://bugs.python.org/issue37631

Would you be able to try out a build without utilizing the extension builder macros?

Comment 4 Miro Hrončok 2019-07-30 09:52:22 UTC
Good thinking. Unfortunately, probably not the case, see https://src.fedoraproject.org/rpms/python38/pull-request/39#comment-28408 and below.

Comment 5 Miro Hrončok 2019-07-30 12:29:53 UTC
Python 3.8.0b2 **does not** seem to suffer from the same problem: https://koji.fedoraproject.org/koji/taskinfo?taskID=36671670

So this might be a regression.

Comment 6 Miro Hrončok 2019-07-30 12:50:40 UTC
I will attempt to git bisect this.

Comment 7 Miro Hrončok 2019-07-30 13:05:04 UTC
Function "builtin_id" not defined.
Function "builtin_id" not defined.
Function "builtin_id" not defined.
...

this is on the output even if the tests pass (on b2).

Comment 8 Miro Hrončok 2019-07-30 15:26:22 UTC
bf8e82f976b37856c7d35cdf88a238cb6f57fe65 is the first new commit
commit bf8e82f976b37856c7d35cdf88a238cb6f57fe65
Author: Jeroen Demeyer <J.Demeyer>
Date:   Tue Jul 23 12:39:51 2019 +0200

    [3.8] bpo-36974: separate vectorcall functions for each calling convention (GH-13781) (#14782)

https://github.com/python/cpython/commit/bf8e82f976b37856c7d35cdf88a238cb6f57fe65
https://github.com/python/cpython/pull/13781

Petr, could you have a look?

Comment 9 Petr Viktorin (pviktori) 2019-07-31 10:42:55 UTC
Not this week. If there are no major fires, I'll get to it next week.

Comment 10 Miro Hrončok 2019-07-31 10:45:19 UTC
We are not shipping the debug build of 3.8 yet until Fedora 31 is branched (2019-08-13).
Considering upstream schedule, next beta happens even later.

Next week is fine. Thanks.

Comment 11 Petr Viktorin (pviktori) 2019-08-12 14:58:11 UTC
There are major fires, and I'm swamped with other work.
If anyone would like to help, consider bisecting Fedora's build options: one of them might be the cause here.

Comment 12 Ben Cotton 2019-08-13 16:57:37 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 31 development cycle.
Changing version to '31'.

Comment 13 Ben Cotton 2019-08-13 17:04:42 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 31 development cycle.
Changing version to 31.

Comment 14 Petr Viktorin (pviktori) 2019-09-25 14:19:25 UTC
The backtrace is:

(gdb) set print address off
(gdb) bt 4
#0  builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.0b4/Python/bltinmodule.c:1172
#1  cfunction_vectorcall_O (nargsf=<optimized out>, kwnames=<optimized out>, args=, 
    func=<built-in method id of module object at remote 0x7fffea85edd0>)
    at /builddir/build/BUILD/Python-3.8.0b4/Objects/methodobject.c:481
#2  cfunction_vectorcall_O (func=<built-in method id of module object at remote 0x7fffea85edd0>, args=, 
    nargsf=<optimized out>, kwnames=<optimized out>)
    at /builddir/build/BUILD/Python-3.8.0b4/Objects/methodobject.c:464
#3  _PyObject_Vectorcall (kwnames=0x0, nargsf=9223372036854775809, args=, 
    callable=<built-in method id of module object at remote 0x7fffea85edd0>)
    at /builddir/build/BUILD/Python-3.8.0b4/Include/cpython/abstract.h:92
(More stack frames follow...)

Specifically, "cfunction_vectorcall_O" is listed twice! Once at the start of the function:

#2  cfunction_vectorcall_O (func=<built-in method id of module object at remote 0x7fffea85edd0>, args=, 
    nargsf=<optimized out>, kwnames=<optimized out>)
    at /builddir/build/BUILD/Python-3.8.0b4/Objects/methodobject.c:464
464	cfunction_vectorcall_O(

and once when calling builtin_id():

#1  cfunction_vectorcall_O (nargsf=<optimized out>, kwnames=<optimized out>, args=, 
    func=<built-in method id of module object at remote 0x7fffea85edd0>)
    at /builddir/build/BUILD/Python-3.8.0b4/Objects/methodobject.c:481
481	    PyObject *result = meth(PyCFunction_GET_SELF(func), args[0]);


The "py-up" command walks the backtrace and skips "uninteresting" frames -- ones that aren't _PyEval_EvalFrameDefault, cfunction_vectorcall_*, etc.
In this case, it stops at each cfunction_vectorcall_O, considering it a Python function.

I don't know if this is expected gdb behavior. Will try to dig.

Comment 15 Petr Viktorin (pviktori) 2019-09-25 15:00:17 UTC
OK, I'm officially out of my depth.
Are there any gcc/gdb stack trace experts around?

Comment 16 Charalampos Stratakis 2019-09-25 15:14:14 UTC
Adding needinfo on the gdb maintainer if he could provide some more info.

Also isn't that the same issue upstream? https://bugs.python.org/issue38239

Comment 17 Petr Viktorin (pviktori) 2019-09-26 13:59:19 UTC
No, issue38239 looks like a different bug :(

Comment 18 Sergio Durigan Junior 2019-09-26 18:09:30 UTC
I'm building the latest Python3 package on Rawhide now, will try to reproduce it and then investigate.

Comment 20 Sergio Durigan Junior 2019-09-27 04:33:57 UTC
(In reply to Miro Hrončok from comment #19)
> You might need to revert this:
> https://src.fedoraproject.org/rpms/python3/c/
> 2d19c7ecdce73a9e51d4a64916761d3e4d69eae9?branch=master

Yes, I was able to reproduce the failure here after editing python3.spec.

I still don't know what's causing it.  There is a chance that this is due to GCC performing some partial inlining optimization, but I'm not sure.  I'll keep you posted.

Comment 21 Victor Stinner 2019-09-27 14:19:12 UTC
> Yes, I was able to reproduce the failure here after editing python3.spec.

I don't understand why test_gdb is run.

I checked Koji build logs: the Python debug build is built using gcc -O2. test_gdb is skipped unless -O0 or -Og is found in CFLAGS (PY_CFLAGS from sysconfig):
https://github.com/python/cpython/blob/14ddca726a8cd337d0461934374b5e6bf65bf812/Lib/test/support/__init__.py#L1678

I'm trying to reproduce the issue locally, but I still only see -O2 in build logs (no other -O<something> flag).

On Fedora Rawhide, I'm building the master branch of https://src.fedoraproject.org/rpms/python3.git modified to enable test_gdb:

diff --git a/python3.spec b/python3.spec
index 46b32c5..599b4ee 100644
--- a/python3.spec
+++ b/python3.spec
@@ -1031,10 +1031,6 @@ CheckPython() {
     %if %{with bootstrap}
     -x test_distutils \
     %endif
-    -x test_gdb \
-    %ifarch %{mips64}
-    -x test_ctypes \
-    %endif
 
   echo FINISHED: CHECKING OF PYTHON FOR CONFIGURATION: $ConfName

--

vstinner@rawhide$ rpm -q python3
python3-3.8.0~b4-1.fc32.x86_64

vstinner@rawhide$ python
Python 3.8.0b4 (default, Aug 30 2019, 00:00:00) 
[GCC 9.2.1 20190827 (Red Hat 9.2.1-1)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import sysconfig
>>> sysconfig.get_config_var('PY_CFLAGS')
'-Wno-unused-result -Wsign-compare -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DNDEBUG  -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches   -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches   -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv  -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches   -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv  -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches   -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv'
>>> '-O0' in sysconfig.get_config_var('PY_CFLAGS')
False
>>> '-Og' in sysconfig.get_config_var('PY_CFLAGS')
False

Comment 22 Victor Stinner 2019-09-27 19:58:11 UTC
Oops sorry, the issue is about python3-debug, not python3. python3-debug is compiled with -Og:

vstinner@rawhide$ python3-debug
Python 3.8.0b4 (default, Aug 30 2019, 00:00:00) 
[GCC 9.2.1 20190827 (Red Hat 9.2.1-1)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import sysconfig
>>> sysconfig.get_config_var('PY_CFLAGS')
'-Wno-unused-result -Wsign-compare -DDYNAMIC_ANNOTATIONS_ENABLED=1  -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches   -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches   -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv  -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches   -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv  -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches   -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -D_GNU_SOURCE -fPIC -fwrapv  -Og'
>>> '-Og' in sysconfig.get_config_var('PY_CFLAGS').split()
True

I managed to reproduce the bug when I build the python3 package, but not when I build python3 manually from source. Example:

$ LD_LIBRARY_PATH=$PWD PYTHONPATH=$PWD/Lib gdb -args ./python Lib/test/gdb_sample.py
# First run just to load symbols
(gdb) run

(gdb) b builtin_id
(gdb) run

Breakpoint 1, builtin_id (self=0x7fffea857dd0, v=42) at /home/vstinner/rpmbuild/BUILD/Python-3.8.0b4/Python/bltinmodule.c:1172
1172	    PyObject *id = PyLong_FromVoidPtr(v);


"Good", expected behavior:
---------------------------------------
(gdb) py-bt
Traceback (most recent call first):
  <built-in method id of module object at remote 0x7fffea84ce30>
  File "Lib/test/gdb_sample.py", line 10, in baz
    id(42)
  File "Lib/test/gdb_sample.py", line 7, in bar
    baz(a, b, c)
  File "Lib/test/gdb_sample.py", line 4, in foo
    bar(a, b, c)
  File "Lib/test/gdb_sample.py", line 12, in <module>
    foo(1, 2, 3)

(gdb) py-bt-full
#1 <built-in method id of module object at remote 0x7fffea84ce30>
#4 Frame 0x7fffea7763f0, for file Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))
    id(42)
#10 Frame 0x7fffea7df410, for file Lib/test/gdb_sample.py, line 7, in bar (a=1, b=2, c=3)
    baz(a, b, c)
#16 Frame 0x7fffea7d8a50, for file Lib/test/gdb_sample.py, line 4, in foo (a=1, b=2, c=3)
    bar(a, b, c)
#22 Frame 0x46ec30, for file Lib/test/gdb_sample.py, line 12, in <module> ()
    foo(1, 2, 3)

(gdb) py-up
#4 Frame 0x7fffea7763f0, for file Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))
    id(42)

(gdb) py-up
#10 Frame 0x7fffea7df410, for file Lib/test/gdb_sample.py, line 7, in bar (a=1, b=2, c=3)
    baz(a, b, c)

(gdb) frame 0
#0  builtin_id (self=0x7fffea84ce30, v=42) at Python/bltinmodule.c:1171
1171	{

(gdb) frame 1
#1  0x00007ffff7b3eee4 in cfunction_vectorcall_O (func=<built-in method id of module object at remote 0x7fffea84ce30>, args=0x7fffea776568, nargsf=<optimized out>, kwnames=0x0) at Objects/methodobject.c:481
481	    PyObject *result = meth(PyCFunction_GET_SELF(func), args[0]);

(gdb) frame 2
#2  0x00007ffff7c4c750 in _PyObject_Vectorcall (kwnames=0x0, nargsf=9223372036854775809, args=<optimized out>, callable=<built-in method id of module object at remote 0x7fffea84ce30>) at ./Include/cpython/abstract.h:127
127	    res = func(callable, args, nargsf, kwnames);

(gdb) frame 3
#3  call_function (kwnames=0x0, oparg=<optimized out>, pp_stack=<synthetic pointer>, tstate=0x408c40) at Python/ceval.c:4987
4987	        x = _PyObject_Vectorcall(func, stack, nargs | PY_VECTORCALL_ARGUMENTS_OFFSET, kwnames);
---------------------------------------


"Bad", surprising backtrace:
---------------------------------------
(gdb) py-bt
Traceback (most recent call first):
  <built-in method id of module object at remote 0x7fffea857dd0>
  <built-in method id of module object at remote 0x7fffea857dd0>
  File "../../Lib/test/gdb_sample.py", line 10, in baz
    id(42)
  File "../../Lib/test/gdb_sample.py", line 7, in bar
    baz(a, b, c)
  File "../../Lib/test/gdb_sample.py", line 4, in foo
    bar(a, b, c)
  File "../../Lib/test/gdb_sample.py", line 12, in <module>
    foo(1, 2, 3)

(gdb) py-bt-full
#1 <built-in method id of module object at remote 0x7fffea857dd0>
#2 <built-in method id of module object at remote 0x7fffea857dd0>
#5 Frame 0x7fffea7823f0, for file ../../Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))
    id(42)
#10 Frame 0x7fffea7eb410, for file ../../Lib/test/gdb_sample.py, line 7, in bar (a=1, b=2, c=3)
    baz(a, b, c)
#14 Frame 0x7fffea7e4a50, for file ../../Lib/test/gdb_sample.py, line 4, in foo (a=1, b=2, c=3)
    bar(a, b, c)
#18 Frame 0x5555555c3dd0, for file ../../Lib/test/gdb_sample.py, line 12, in <module> ()
    foo(1, 2, 3)

(gdb) py-up
#2 <built-in method id of module object at remote 0x7fffea857dd0>

(gdb) py-up
#5 Frame 0x7fffea7823f0, for file ../../Lib/test/gdb_sample.py, line 10, in baz (args=(1, 2, 3))
    id(42)


(gdb) frame 0
#0  builtin_id (self=0x7fffea857dd0, v=42) at /home/vstinner/rpmbuild/BUILD/Python-3.8.0b4/Python/bltinmodule.c:1172
1172	    PyObject *id = PyLong_FromVoidPtr(v);

(gdb) frame 1
#1  0x00007ffff7bbbe13 in cfunction_vectorcall_O (nargsf=<optimized out>, kwnames=<optimized out>, args=0x7fffea782568, func=<built-in method id of module object at remote 0x7fffea857dd0>)
    at /home/vstinner/rpmbuild/BUILD/Python-3.8.0b4/Objects/methodobject.c:481
481	    PyObject *result = meth(PyCFunction_GET_SELF(func), args[0]);

(gdb) frame 2
#2  cfunction_vectorcall_O (func=<built-in method id of module object at remote 0x7fffea857dd0>, args=0x7fffea782568, nargsf=<optimized out>, kwnames=<optimized out>)
    at /home/vstinner/rpmbuild/BUILD/Python-3.8.0b4/Objects/methodobject.c:464
464	cfunction_vectorcall_O(

(gdb) frame 3
#3  0x00007ffff7a8e673 in _PyObject_Vectorcall (kwnames=0x0, nargsf=9223372036854775809, args=0x7fffea782568, callable=<built-in method id of module object at remote 0x7fffea857dd0>)
    at /home/vstinner/rpmbuild/BUILD/Python-3.8.0b4/Include/cpython/abstract.h:92
92	    return *ptr;

(gdb) frame 4
#4  call_function (kwnames=0x0, oparg=<optimized out>, pp_stack=<synthetic pointer>, tstate=0x55555555d5e0) at /home/vstinner/rpmbuild/BUILD/Python-3.8.0b4/Python/ceval.c:4987
4987	        x = _PyObject_Vectorcall(func, stack, nargs | PY_VECTORCALL_ARGUMENTS_OFFSET, kwnames);
---------------------------------------


The difference is how gdb sees _PyObject_Vectorcall() and cfunction_vectorcall_O() function calls.

                                                                           
static inline vectorcallfunc
_PyVectorcall_Function(PyObject *callable)
{
    ...
    ptr = (vectorcallfunc*)(((char *)callable) + offset);
    return *ptr;
}


static inline PyObject *
_PyObject_Vectorcall(PyObject *callable, PyObject *const *args,
                     size_t nargsf, PyObject *kwnames)
{
    ...
    func = _PyVectorcall_Function(callable);
    if (func == NULL) {
        ...
    }
    res = func(callable, args, nargsf, kwnames);
    return _Py_CheckFunctionResult(callable, res, NULL);
}

static PyObject *
cfunction_vectorcall_O(
    PyObject *func, PyObject *const *args, size_t nargsf, PyObject *kwnames)
{ ... }


In the "bad" trace:

* the frame 3 is shown as "_PyObject_Vectorcall()", but it shows code which comes form a different function _PyVectorcall_Function(): "return *ptr;".
* cfunction_vectorcall_O() is shown in two frames: frame 1 and frame 2. In the "good" trace, it's only shown once (frame 1).

--

In my experience, using gdb on Python compiled with gcc -Og is painful: some variables are "<optimized out>" which makes the debug experience painful, and execute the code "step by step" (line by line) goes backward or jump to an unrelated line, because of optimizations.

In my experience, gcc -O0 provides the best experience to debug Python in gdb.

I cannot say if gcc -Og has "bugs", if gdb is not smart enough to inspect machine code generated by gcc, or if Python should be compiled with -O0 for debug build.

Until compiler and debugger experts decide, I will continue to use -O0 to develop, as I was always doing :-D

Comment 23 Petr Viktorin (pviktori) 2019-10-01 13:13:02 UTC
Sergio, do you think we should switch from -Og to -O0? Are there any downsides?

Comment 24 Miro Hrončok 2019-10-01 13:16:51 UTC
A side note:

https://gcc.gnu.org/onlinedocs/gcc/Optimize-Options.html

-Og
Optimize debugging experience. -Og should be the optimization level of choice for the standard edit-compile-debug cycle, offering a reasonable level of optimization while maintaining fast compilation and a good debugging experience. It is a better choice than -O0 for producing debuggable code because some compiler passes that collect debug information are disabled at -O0.

Like -O0, -Og completely disables a number of optimization passes so that individual options controlling them have no effect. Otherwise -Og enables all -O1 optimization flags except for those that may interfere with debugging:

-fbranch-count-reg  -fdelayed-branch 
-fdse  -fif-conversion  -fif-conversion2  
-finline-functions-called-once 
-fmove-loop-invariants  -fssa-phiopt 
-ftree-bit-ccp  -ftree-dse  -ftree-pta  -ftree-sra

Comment 25 Victor Stinner 2019-10-01 13:50:58 UTC
"It is a better choice than -O0 for producing debuggable code because some compiler passes that collect debug information are disabled at -O0."

Well. Using -Og, gdb is unable to inspect multiple function arguments, like:

"#1  0x00007ffff7bbbe13 in cfunction_vectorcall_O (nargsf=<optimized out>, kwnames=<optimized out>, ..."

Moreover, using -Og, the call stack is "surprising" and doesn't make any sense for some frames.

Comment 26 Sergio Durigan Junior 2019-10-01 18:18:56 UTC
Victor, thank you very much for your thorough analysis of the problem!  I agree with your findings, and I also agree with the conclusion.

Miro, I'm not a GCC expert, but I always use -O0 -g3 personally when compiling things for debugging.  -O0 disables optimizations, and -g3 includes the usual debuginfo + information about macros and defines (you can also use -g, which doesn't include info about macros).

I'm asking the GCC folks about this, but it is possible that -Og produces things that GDB still can't fully consume when debugging the inferior.  If you can, I think that switching over to -O0 -g should solve this specific issue.

I'll let you know when the GCC folks reply to my questions.

Comment 27 Sergio Durigan Junior 2019-10-02 13:37:47 UTC
So, I talked to the GCC folks yesterday.  There doesn't seem to be a consensus on what is the best option for debuginfo generation; Jakub Jelinek said that "sometimes -Og is better, other times -O0 -g, it depends on for what".  I will still go with my experience and stick to -O0 -g whenever I need, because that's what reliably delivers the best debuginfo IMO.  I suggested that GCC should update its documentation and not blindly suggest -Og over -O0 -g, since it has more drawbacks than benefits.

There is at least one open bug against GCC which covers the issue of optimized-out variables when using -Og: https://gcc.gnu.org/bugzilla/show_bug.cgi?id=78685 .  As far as I have researched, GDB doesn't have any open bugs about it.

It's interesting to see (from the bug mentioned above) that the Emacs developers faced the same problem as you guys, and are still using -O0 -g when debuginfo generation is a need: https://lists.gnu.org/archive/html/emacs-devel/2016-12/msg00199.html.

So yeah, all in all I definitely recommend you to use -O0 -g instead of -Og for the debug build.

Comment 28 Victor Stinner 2019-10-02 16:38:34 UTC
I created https://bugs.python.org/issue38350 upstream to propose to replace -Og with -O0 when building Python in debug mode (./configure --with-pydebug).

Comment 29 Victor Stinner 2019-11-12 14:21:12 UTC
Using -O0 is incompatible with "-Wp,-D_FORTIFY_SOURCE=2": we should try to compile Python with -O0 and without _FORTIFY_SOURCE.

Last time I tried, I failed to inject -O0 at the right place. Miro fixed the specfile to put -Og at the right place. So I can be tried again.

Comment 30 Petr Viktorin (pviktori) 2020-01-07 14:53:22 UTC
The question we need answered to move forward is:
Is it OK from the gcc & gdb point of view that a function appears twice in the GDB backtrace?

#1  cfunction_vectorcall_O (nargsf=<optimized out>, kwnames=<optimized out>, args=, 
    func=<built-in method id of module object at remote 0x7fffea85edd0>)
    at /builddir/build/BUILD/Python-3.8.0b4/Objects/methodobject.c:481
#2  cfunction_vectorcall_O (func=<built-in method id of module object at remote 0x7fffea85edd0>, args=, 
    nargsf=<optimized out>, kwnames=<optimized out>)
    at /builddir/build/BUILD/Python-3.8.0b4/Objects/methodobject.c:464


If it is, we need to change the Python test suite.
If not, it's a gcc/gdb bug.

Comment 31 Charalampos Stratakis 2020-01-07 14:55:26 UTC
David would you be able to provide some info here? I understand you worked extensively on Python's integration with GDB.

Comment 32 Dave Malcolm 2020-01-07 15:17:44 UTC
I implemented it, but I haven't touched it or CPython in a few years.

Re comment #30, it's kind of weird to see two frames for "cfunction_vectorcall_O", with different parameters.

Looking at an old version of methodobject.c:
  https://github.com/python/cpython/blob/bf8e82f976b37856c7d35cdf88a238cb6f57fe65/Objects/methodobject.c
(though it's changed since),

Line 464 of methodobject.c was here:

463 static PyObject *
464 cfunction_vectorcall_O(
465     PyObject *func, PyObject *const *args, size_t nargsf, PyObject *kwnames)
466 {

whereas line 481 was:

481     PyObject *result = meth(PyCFunction_GET_SELF(func), args[0]);

where:

477     PyCFunction meth = (PyCFunction)cfunction_enter_call(func);

so frame #2 is the call to cfunction_vectorcall_O, and frame #1 is the call to the "meth" function pointer.  I'm not sure why gdb isn't grokking which function is being called here as "meth".

The purpose of test_gdb is to test the user experience for someone hacking on an CPython extension module (or on CPython itself) when they're trying to get a backtrace from gdb that's meaningful at the Python level.

From that point of view, what's important in this test case is to figure out what Python-level function is being called.  Frame #2 has the "func" info available, frame #1 doesn't, so maybe filtering to just those frames for which "func" can be grokked might be appropriate here.

Comment 33 Petr Viktorin (pviktori) 2020-01-07 15:36:43 UTC
I don't think changing the tests would be a prblem, but I don't want to work around a (possibly unknown) bug.
So I'd like confirmation from gcc/gdb folks that this is expected or acceptable. (Or at least a known WONTFIX bug.)

Comment 34 Victor Stinner 2020-01-08 16:12:39 UTC
For me, the main pain point are all these <optimized out> variables and function arguments. For example, it is not possible to inspect arguments of this function call which makes debugging a very painful experience:

#1  cfunction_vectorcall_O (nargsf=<optimized out>, kwnames=<optimized out>, args=, 
    func=<built-in method id of module object at remote 0x7fffea85edd0>)
    at /builddir/build/BUILD/Python-3.8.0b4/Objects/methodobject.c:481

That's caused by -Og optimizations. With -O0, gdb is able to inspect all variables, all function arguments, and there is no strange call track caused by inlining. -Og enables function inlining to make the binary more efficient, but gdb doesn't understand that and shows "broken" call stacks, as seen here.

For all these reasons, I suggest to disable _FORTIFY_SOURCE and compile Python with -O0 for the debug build. python3-dbg is not designed to be used in production but reserved to debug a tricky crash in a C extension. Debug build contains more *runtime* checks and so may detect bugs earlier. Moreover, the debug build should behave better in gdb and similar debuggers.

The regular Python binary is highly optimized (PGO + LTO) which makes it barely usable in a debugger. Moreover, when Python is built in release mode, assertions and many runtime checks are stripped out.

Comment 35 Ben Cotton 2020-02-11 15:41:19 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 32 development cycle.
Changing version to 32.

Comment 36 Petr Viktorin (pviktori) 2020-03-26 12:02:02 UTC
I can't reproduce this issue any more. Scratch builds pass on most (but not all) architectures: 
f32: https://koji.fedoraproject.org/koji/taskinfo?taskID=42772162
f31: https://koji.fedoraproject.org/koji/taskinfo?taskID=42762865

Comment 37 Charalampos Stratakis 2020-03-27 13:53:10 UTC
Indeed the issue seems to be gone with the latest gcc version.

Possibly a compiler optimization that was making the function split into two, hence gdb was seeing the function twice? Maybe something else entirely? Nevertheless currently we are facing failures on arm32 and s390x with some regex not matching due to debug information being optimized out on -Og, e.g.:

FAIL: test_locals_after_up (test.test_gdb.PyLocalsTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/builddir/build/BUILD/Python-3.8.2/Lib/test/test_gdb.py", line 967, in test_locals_after_up
    self.assertMultilineMatches(bt,
  File "/builddir/build/BUILD/Python-3.8.2/Lib/test/test_gdb.py", line 279, in assertMultilineMatches
    self.fail(msg='%r did not match %r' % (actual, pattern))
AssertionError: 'Breakpoint 1 (builtin_id) pending.\n[Thread debugging using libthread_db enabled]\nUsing host libthread_db library "/lib/libthread_db.so.1".\n\nBreakpoint 1, builtin_id (self=, v=42) at /builddir/build/BUILD/Python-3.8.2/Python/bltinmodule.c:1171\n1171\t{\n#4 (frame information optimized out)\n#10 (frame information optimized out)\n' did not match '.*\\na = 1\\nb = 2\\nc = 3\\n.*'

I'll close this one and open a new bugzilla to track the latest failures.


Note You need to log in before you can comment on or make changes to this bug.