[Bug 2063094] Re: unattended-upgrades is running forever

Thu May 30 10:26:44 UTC 2024

I'm seeing very different traces. Sorry. :)

I have processes which appear stuck and which have been using more than
11 weeks of CPU time over the past 132 days. No idea if it was in only
one run (I think I looked at CPU time less than 132 days ago, and even
less than 11 weeks ago, so it probably hasn't been stuck for 11 weeks).
This happens in three LXC containers which run debian stable. It seems I
ran out of space on the containers, but definitely not 11 weeks ago,
maybe two weeks ago at most.

Traces I see:

  Thread 1 (Thread 0x7f9ca69f4040 (LWP 115) "unattended-upgr"):
  #0  0x00007f9ca6a7ad26 in _xbegin () at /usr/lib/gcc/x86_64-linux-gnu/12/include/rtmintrin.h:52
  #1  __GI___lll_trylock_elision (futex=0x2b0c9a0, adapt_count=0x89) at ../sysdeps/unix/sysv/linux/x86/elision-trylock.c:46
  #2  0x0000000000a840d8 in _PyRuntime ()
  #3  0x000000000058a52a in PyArg_ParseTupleAndKeywords (args=<optimized out>, keywords=<optimized out>, format=<optimized out>, kwlist=<optimized out>) at ../Python/getargs.c:1394
  #4  0x000000000058a245 in acquire_timed (timeout=<optimized out>, lock=0x7fffcf0f55f0) at ../Modules/_threadmodule.c:98
  #5  lock_PyThread_acquire_lock (self=0x2b0c9a0, args=<optimized out>, kwds=<optimized out>) at ../Modules/_threadmodule.c:179
  #6  0x0000000000550bbe in method_vectorcall_VARARGS_KEYWORDS (func=0x7f9ca6976f70, args=0x7f9ca6cff398, nargsf=<optimized out>, kwnames=<optimized out>) at ../Objects/descrobject.c:364
  #7  0x000000000053ac2c in _PyObject_VectorcallTstate (kwnames=<optimized out>, nargsf=<optimized out>, args=<optimized out>, callable=0x7f9ca6976f70, tstate=0xa840d8 <_PyRuntime+166328>) at ../Include/internal/pycore_call.h:92
  #8  PyObject_Vectorcall (callable=0x7f9ca6976f70, args=<optimized out>, nargsf=<optimized out>, kwnames=<optimized out>) at ../Objects/call.c:299
  #9  0x000000000052b940 in _PyEval_EvalFrameDefault (tstate=<optimized out>, frame=<optimized out>, throwflag=<optimized out>) at ../Python/ceval.c:4772
  #10 0x000000000052360b in _PyEval_EvalFrame (throwflag=0, frame=0x7f9ca6cff020, tstate=0xa840d8 <_PyRuntime+166328>) at ../Include/internal/pycore_ceval.h:73
  #11 _PyEval_Vector (args=0x0, argcount=0, kwnames=0x0, locals=<optimized out>, func=0x7f9ca69ba020, tstate=0xa840d8 <_PyRuntime+166328>) at ../Python/ceval.c:6435
  #12 PyEval_EvalCode (co=0x2959f10, globals=<optimized out>, locals=<optimized out>) at ../Python/ceval.c:1154
  #13 0x0000000000647497 in run_eval_code_obj (tstate=0xa840d8 <_PyRuntime+166328>, co=0x2959f10, globals=0x7f9ca69dec80, locals=0x7f9ca69dec80) at ../Python/pythonrun.c:1714
  #14 0x0000000000644d4f in run_mod (mod=<optimized out>, filename=<optimized out>, globals=0x7f9ca69dec80, locals=0x7f9ca69dec80, flags=<optimized out>, arena=<optimized out>) at ../Python/pythonrun.c:1735
  #15 0x0000000000651010 in pyrun_file (fp=fp at entry=0x2906830, filename=filename at entry=0x7f9ca6918f80, start=start at entry=257, globals=globals at entry=0x7f9ca69dec80, locals=locals at entry=0x7f9ca69dec80, closeit=closeit at entry=1, flags=0x7fffcf0f5a68) at ../Python/pythonrun.c:1630
  #16 0x0000000000650d5b in _PyRun_SimpleFileObject (fp=fp at entry=0x2906830, filename=filename at entry=0x7f9ca6918f80, closeit=closeit at entry=1, flags=flags at entry=0x7fffcf0f5a68) at ../Python/pythonrun.c:440
  #17 0x0000000000650b84 in _PyRun_AnyFileObject (fp=0x2906830, filename=0x7f9ca6918f80, closeit=1, flags=0x7fffcf0f5a68) at ../Python/pythonrun.c:79
  #18 0x000000000064f90f in pymain_run_file_obj (skip_source_first_line=0, filename=0x7f9ca6918f80, program_name=0x7f9ca69e02b0) at ../Modules/main.c:360
  #19 pymain_run_file (config=0xa6a120 <_PyRuntime+59904>) at ../Modules/main.c:379
  #20 pymain_run_python (exitcode=0x7fffcf0f5a64) at ../Modules/main.c:601
  #21 Py_RunMain () at ../Modules/main.c:680
  #22 0x00000000006275c7 in Py_BytesMain (argc=<optimized out>, argv=<optimized out>) at ../Modules/main.c:734
  #23 0x00007f9ca6a1c1ca in ?? () from /lib/x86_64-linux-gnu/libc.so.6
  #24 0x00007fffcf0f5c80 in ?? ()
  #25 0x0000000000627530 in frame_dummy ()
  #26 0x0000000300400040 in ?? ()
  #27 0x00007fffcf0f5c98 in ?? ()
  #28 0x00007fffcf0f5c98 in ?? ()
  #29 0x108cfa692055372a in ?? ()
  #30 0x0000000000000000 in ?? ()

Another case:

  Thread 1 (Thread 0x7f9ca69f4040 (LWP 115) "unattended-upgr"):
  #0  0x00007f9ca643818d in _dbus_header_cache_check (field=5, header=0x9156278) at ../../../dbus/dbus-marshal-header.c:252
  #1  _dbus_header_get_field_basic (header=header at entry=0x9156278, field=field at entry=5, type=type at entry=117, value=value at entry=0x7fffcf0f5484) at ../../../dbus/dbus-marshal-header.c:1374
  #2  0x00007f9ca643cde1 in dbus_message_get_reply_serial (message=message at entry=0x9156270) at ../../../dbus/dbus-message.c:1202
  #3  0x00007f9ca6432034 in check_for_reply_unlocked (client_serial=3814221, connection=0x2a0f1e0) at ../../../dbus/dbus-connection.c:2287
  #4  check_for_reply_and_update_dispatch_unlocked (connection=connection at entry=0x2a0f1e0, pending=pending at entry=0x2a40c60) at ../../../dbus/dbus-connection.c:2355
  #5  0x00007f9ca6432233 in _dbus_connection_block_pending_call (pending=0x2a40c60) at ../../../dbus/dbus-connection.c:2474
  #6  0x00007f9ca644404a in dbus_pending_call_block (pending=<optimized out>) at ../../../dbus/dbus-pending-call.c:768
  #7  0x00007f9ca6432872 in dbus_connection_send_with_reply_and_block (connection=0x2a0f1e0, message=message at entry=0xb4df650, timeout_milliseconds=timeout_milliseconds at entry=2000, error=error at entry=0x7fffcf0f5600) at ../../../dbus/dbus-connection.c:3586
  #8  0x00007f9ca647ed3d in Connection_send_message_with_reply_and_block (self=0x7f9ca5ebb890, args=<optimized out>) at ../dbus_bindings/conn-methods.c:501
  #9  0x00000000005230d0 in method_vectorcall_VARARGS (func=0x7f9ca6506f70, args=0x7f9ca6cff508, nargsf=<optimized out>, kwnames=<optimized out>) at ../Objects/descrobject.c:330
  #10 0x000000000053ac2c in _PyObject_VectorcallTstate (kwnames=<optimized out>, nargsf=<optimized out>, args=<optimized out>, callable=0x7f9ca6506f70, tstate=0xa840d8 <_PyRuntime+166328>) at ../Include/internal/pycore_call.h:92
  #11 PyObject_Vectorcall (callable=0x7f9ca6506f70, args=<optimized out>, nargsf=<optimized out>, kwnames=<optimized out>) at ../Objects/call.c:299
  #12 0x000000000052b940 in _PyEval_EvalFrameDefault (tstate=<optimized out>, frame=<optimized out>, throwflag=<optimized out>) at ../Python/ceval.c:4772
  #13 0x000000000052360b in _PyEval_EvalFrame (throwflag=0, frame=0x7f9ca6cff020, tstate=0xa840d8 <_PyRuntime+166328>) at ../Include/internal/pycore_ceval.h:73
  #14 _PyEval_Vector (args=0x0, argcount=0, kwnames=0x0, locals=<optimized out>, func=0x7f9ca69ba020, tstate=0xa840d8 <_PyRuntime+166328>) at ../Python/ceval.c:6435
  #15 PyEval_EvalCode (co=0x2959f10, globals=<optimized out>, locals=<optimized out>) at ../Python/ceval.c:1154
  #16 0x0000000000647497 in run_eval_code_obj (tstate=0xa840d8 <_PyRuntime+166328>, co=0x2959f10, globals=0x7f9ca69dec80, locals=0x7f9ca69dec80) at ../Python/pythonrun.c:1714
  #17 0x0000000000644d4f in run_mod (mod=<optimized out>, filename=<optimized out>, globals=0x7f9ca69dec80, locals=0x7f9ca69dec80, flags=<optimized out>, arena=<optimized out>) at ../Python/pythonrun.c:1735
  #18 0x0000000000651010 in pyrun_file (fp=fp at entry=0x2906830, filename=filename at entry=0x7f9ca6918f80, start=start at entry=257, globals=globals at entry=0x7f9ca69dec80, locals=locals at entry=0x7f9ca69dec80, closeit=closeit at entry=1, flags=0x7fffcf0f5a68) at ../Python/pythonrun.c:1630
  #19 0x0000000000650d5b in _PyRun_SimpleFileObject (fp=fp at entry=0x2906830, filename=filename at entry=0x7f9ca6918f80, closeit=closeit at entry=1, flags=flags at entry=0x7fffcf0f5a68) at ../Python/pythonrun.c:440
  #20 0x0000000000650b84 in _PyRun_AnyFileObject (fp=0x2906830, filename=0x7f9ca6918f80, closeit=1, flags=0x7fffcf0f5a68) at ../Python/pythonrun.c:79
  #21 0x000000000064f90f in pymain_run_file_obj (skip_source_first_line=0, filename=0x7f9ca6918f80, program_name=0x7f9ca69e02b0) at ../Modules/main.c:360
  #22 pymain_run_file (config=0xa6a120 <_PyRuntime+59904>) at ../Modules/main.c:379
  #23 pymain_run_python (exitcode=0x7fffcf0f5a64) at ../Modules/main.c:601
  #24 Py_RunMain () at ../Modules/main.c:680
  #25 0x00000000006275c7 in Py_BytesMain (argc=<optimized out>, argv=<optimized out>) at ../Modules/main.c:734
  #26 0x00007f9ca6a1c1ca in ?? () from /lib/x86_64-linux-gnu/libc.so.6
  #27 0x00007fffcf0f5c80 in ?? ()
  #28 0x0000000000627530 in frame_dummy ()
  #29 0x0000000300400040 in ?? ()
  #30 0x00007fffcf0f5c98 in ?? ()
  #31 0x00007fffcf0f5c98 in ?? ()
  #32 0x108cfa692055372a in ?? ()
  #33 0x0000000000000000 in ?? ()

It seems I only see these two backtraces. I'll dive into the python side later on.

Using dbus-monitor --system, I see the following activity every three
seconds:

method call time=1717064374.442063 sender=:1.1 -> destination=org.freedesktop.login1 serial=3814267 path=/org/freedesktop/login1; interface=org.freedesktop.login1.Manager; member=Inhibit
   string "shutdown"
   string "Unattended Upgrades Shutdown"
   string "Stop ongoing upgrades or perform upgrades before shutdown"
   string "delay"

Every ... I see errors in batch (they are only spaced every 30µs) for
all the messages that have been sent since the last error batch:

error time=1717064399.444494 sender=org.freedesktop.DBus -> destination=:1.1 error_name=org.freedesktop.DBus.Error.TimedOut reply_serial=3814267
   string "Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)"

In summary: 9 messages sent 3 seconds apart and 25 seconds after the
first of these, errors for all of the 9 messages.

These LXC containers have been created years ago using LXC templates and
I never gave a thought to logind in their context.

The rate of dbus messages is pretty low and dbus-daemon CPU time is
quite low at less than 14 minutes total.

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to unattended-upgrades in Ubuntu.
https://bugs.launchpad.net/bugs/2063094

Title:
  unattended-upgrades is running forever

Status in unattended-upgrades package in Ubuntu:
  Confirmed

Bug description:
    28433 root      39  19  354904 111480  71296 R  99.7   0.7 107:29.26
  unattended-upgr

  ProblemType: Bug
  DistroRelease: Ubuntu 24.04
  Package: unattended-upgrades 2.9.1+nmu4ubuntu1
  ProcVersionSignature: Ubuntu 6.8.0-28.28-generic 6.8.1
  Uname: Linux 6.8.0-28-generic x86_64
  NonfreeKernelModules: zfs
  ApportVersion: 2.28.0-0ubuntu1
  Architecture: amd64
  CasperMD5CheckResult: pass
  CurrentDesktop: ubuntu:GNOME
  Date: Mon Apr 22 10:27:34 2024
  InstallationDate: Installed on 2022-01-07 (836 days ago)
  InstallationMedia: Ubuntu 21.10 "Impish Indri" - Release amd64 (20211012)
  PackageArchitecture: all
  SourcePackage: unattended-upgrades
  UpgradeStatus: Upgraded to noble on 2024-04-10 (12 days ago)

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/unattended-upgrades/+bug/2063094/+subscriptions