Fix test client failing periodically

added Continuous Integration priorityhigh typebug labels

assigned to @nbugel

So this is not just related to XRootD I think; there are some other fishy things in the logs when this goes wrong.

In CI it's the ObjectStore that is segfaulting

(gdb) bt full
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=11, no_tid=no_tid@entry=0) at pthread_kill.c:44
        tid = <optimized out>
        ret = 0
        pd = <optimized out>
        old_mask = {__val = {0 <repeats 16 times>}}
        ret = <optimized out>
#1  0x00007f6086b7bad3 in __pthread_kill_internal (signo=11, threadid=<optimized out>) at pthread_kill.c:78
No locals.
#2  0x00007f6086b2e686 in __GI_raise (sig=11) at ../sysdeps/posix/raise.c:26
        ret = <optimized out>
#3  0x00007f608b191f94 in skgesigOSCrash () from /usr/lib/oracle/23/client64/lib/libclntsh.so.23.1
No symbol table info available.
#4  0x00007f608b9ab8c9 in kpeDbgSignalHandler () from /usr/lib/oracle/23/client64/lib/libclntsh.so.23.1
No symbol table info available.
#5  0x00007f608b192327 in skgesig_sigactionHandler () from /usr/lib/oracle/23/client64/lib/libclntsh.so.23.1
No symbol table info available.
#6  <signal handler called>
No locals.
#7  cta::utils::segfault () at /usr/src/debug/cta-5-9971143git80cfccd5.el9.x86_64/common/utils/utils.cpp:933
No locals.
#8  0x00007f608f0ff3b0 in cta::objectstore::BackendPopulator::~BackendPopulator (this=0xfc3bb0, __in_chrg=<optimized out>)
    at /usr/src/debug/cta-5-9971143git80cfccd5.el9.x86_64/objectstore/BackendPopulator.cpp:82
        params = {m_context = @0xfc3c80, m_names = std::set with 1 element = {[0] = "errorMessage"}}
        ex = @0x7f607803d080: {<std::exception> = {_vptr.exception = 0x7f608f2515c8 <vtable for cta::objectstore::Agent::AgentStillOwnsObjects+16>}, 
          m_message = {<std::basic_ostream<char, std::char_traits<char> >> = {<std::basic_ios<char, std::char_traits<char> >> = {<std::ios_base> = {
                  _vptr.ios_base = 0x7f6087010558 <vtable for std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >+64>, static boolalpha = std::_S_boolalpha, 
                  static dec = std::_S_dec, static fixed = std::_S_fixed, static hex = std::_S_hex, static internal = std::_S_internal, static left = std::_S_left, static oct = std::_S_oct, 
                  static right = std::_S_right, static scientific = std::_S_scientific, static showbase = std::_S_showbase, static showpoint = std::_S_showpoint, static showpos = std::_S_showpos, 
                  static skipws = std::_S_skipws, static unitbuf = std::_S_unitbuf, static uppercase = std::_S_uppercase, static adjustfield = std::_S_adjustfield, static basefield = std::_S_basefield, 
                  static floatfield = std::_S_floatfield, static badbit = std::_S_badbit, static eofbit = std::_S_eofbit, static failbit = std::_S_failbit, static goodbit = std::_S_goodbit, 
                  static app = std::_S_app, static ate = std::_S_ate, static binary = std::_S_bin, static in = std::_S_in, static out = std::_S_out, static trunc = std::_S_trunc, static beg = std::_S_beg, 
                  static cur = std::_S_cur, static end = std::_S_end, _M_precision = 6, _M_width = 0, _M_flags = 4098, _M_exception = std::_S_goodbit, _M_streambuf_state = std::_S_goodbit, 
                  _M_callbacks = 0x0, _M_word_zero = {_M_pword = 0x0, _M_iword = 0}, _M_local_word = {{_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {
                      _M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}}, _M_word_size = 8, 
                  _M_word = 0x7f607803d138, _M_ios_locale = {static none = 0, static ctype = 1, static numeric = 2, static collate = 4, static time = 8, static monetary = 16, static messages = 32, 
                    static all = 63, _M_impl = 0x7f6087017ce0 <(anonymous namespace)::c_locale_impl>}}, _M_tie = 0x0, _M_fill = 0 '\000', _M_fill_init = false, _M_streambuf = 0x7f607803d090, 
                _M_ctype = 0x7f6087017700 <(anonymous namespace)::ctype_c>, _M_num_put = 0x7f6087017690 <(anonymous namespace)::num_put_c>, _M_num_get = 0x7f60870176a0 <(anonymous namespace)::num_get_c>}, 
              _vptr.basic_ostream = 0x7f6087010530 <vtable for std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >+24>}, 
            _M_stringbuf = {<std::basic_streambuf<char, std::char_traits<char> >> = {
                _vptr.basic_streambuf = 0x7f6087010378 <vtable for std::__cxx11::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >+16>, 
                _M_in_beg = 0x7f5f600079f0 "AndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv01-0-443-20250124-00:43:08-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-287-20250124-00:42:57-0-30187"..., 
                _M_in_cur = 0x7f5f600079f0 "AndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv01-0-443-20250124-00:43:08-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-287-20250124-00:42:57-0-30187"..., 
                _M_in_end = 0x7f5f600079f0 "AndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv01-0-443-20250124-00:43:08-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-287-20250124-00:42:57-0-30187"..., 
                _M_out_beg = 0x7f5f600079e0 "In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv01-0-443-20250124-00:43:08-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-287-20250124-"..., 
                _M_out_cur = 0x7f5f60007ab8 "ontainerIfNeeded(): could not delete a presumably empty queue\",\"drive_name\":\"VDSTK01\",\"instance\":\"CI\",\"sched_backend\":\"ceph\",\"SubprocessName\":\"maintenanceHandler\",\"tapeVid\":\"V00101\",\"tapeState\":\"EXPOR"..., _M_out_end = 0x7f5f60007be0 "\006", _M_buf_locale = {static none = 0, static ctype = 1, static numeric = 2, static collate = 4, 
                  static time = 8, static monetary = 16, static messages = 32, static all = 63, _M_impl = 0x7f6087017ce0 <(anonymous namespace)::c_locale_impl>}}, _M_mode = std::_S_out, 
              _M_string = "In Agent::remove"}}, m_what = "", m_backtrace = {
            m_trace = "/lib64/libctacommon.so.0(cta::exception::Backtrace::Backtrace(bool)+0x6b) [0x7f60878f23d1]\n/lib64/libctacommon.so.0(cta::exception::Exception::Exception(std::basic_string_view<char, std::char_traits<c"...}}
        agent = <optimized out>
        agl = <optimized out>
        params = <optimized out>
        ex = <optimized out>
        params = <optimized out>
        ex = <optimized out>
        params = <optimized out>
#9  0x00007f608f0ff537 in cta::objectstore::BackendPopulator::~BackendPopulator (this=0xfc3bb0, __in_chrg=<optimized out>)
    at /usr/src/debug/cta-5-9971143git80cfccd5.el9.x86_64/objectstore/BackendPopulator.cpp:90
        agent = <optimized out>
        agl = <optimized out>
        params = <optimized out>
        ex = <optimized out>
        params = <optimized out>
        ex = <optimized out>
        params = <optimized out>
#10 0x00000000004b766b in std::default_delete<cta::objectstore::BackendPopulator>::operator() (this=0x7ffc06a23138, __ptr=0xfc3bb0) at /usr/include/c++/11/bits/unique_ptr.h:85
No locals.
#11 0x00000000004b396b in std::unique_ptr<cta::objectstore::BackendPopulator, std::default_delete<cta::objectstore::BackendPopulator> >::~unique_ptr (this=0x7ffc06a23138, __in_chrg=<optimized out>)
    at /usr/include/c++/11/bits/unique_ptr.h:361
        __ptr = @0x7ffc06a23138: 0xfc3bb0
        __ptr = <optimized out>
#12 0x00000000004b8255 in cta::OStoreDBInit::~OStoreDBInit (this=0x7ffc06a23130, __in_chrg=<optimized out>) at /usr/src/debug/cta-5-9971143git80cfccd5.el9.x86_64/scheduler/OStoreDB/OStoreDBInit.hpp:30
No locals.
#13 0x00000000004dfb64 in cta::tape::daemon::MaintenanceHandler::exceptionThrowingRunChild (this=0xfc20c0) at /usr/src/debug/cta-5-9971143git80cfccd5.el9.x86_64/tapeserver/daemon/MaintenanceHandler.cpp:390
        sched_db_init = {m_backend = std::unique_ptr<cta::objectstore::Backend> = {get() = 0xf35660}, m_backendPopulator = std::unique_ptr<cta::objectstore::BackendPopulator> = {get() = 0xfc3bb0}, 
          m_agentHeartbeat = std::unique_ptr<cta::objectstore::AgentHeartbeatThread> = {get() = 0x0}}
        sched_db = std::unique_ptr<cta::OStoreDBWithAgent> = {get() = 0x0}
        catalogue = std::unique_ptr<cta::catalogue::Catalogue> = {get() = 0x0}
        scheduler = std::unique_ptr<cta::Scheduler> = {get() = 0x0}
...

created branch 1034-fix-test-client-failing-periodically to address this issue

mentioned in merge request !771

In the stress-test, we also get xrdcp segfaulting periodically. Not sure if this is related

The full stack trace in the client pod is as follows:

(gdb) info threads
  Id   Target Id                           Frame 
* 1    Thread 0x7f77767f9640 (LWP 3051281) init_thread_stop (arg=0x0, hands=0x7f7768015490) at crypto/initthread.c:344
  2    Thread 0x7f7776808840 (LWP 3051156) 0x00007f7777b1f6bf in std::unordered_map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, int, std::hash<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::equal_to<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, int> > >::~unordered_map() () from /lib64/libXrdCl.so.3
(gdb) bt full
#0  init_thread_stop (arg=0x0, hands=0x7f7768015490) at crypto/initthread.c:344
        curr = 0x7f709f76fd65
        prev = 0x0
        tmp = <optimized out>
        gtr = 0x7f77680154b0
#1  0x00007f7776e19c37 in init_thread_stop (hands=0x7f7768015490, arg=0x0) at crypto/initthread.c:330
        curr = <optimized out>
        prev = 0x0
        tmp = <optimized out>
        gtr = <optimized out>
        curr = <optimized out>
        prev = <optimized out>
        tmp = <optimized out>
        gtr = <optimized out>
#2  init_thread_destructor (hands=0x7f7768015490) at crypto/initthread.c:197
No locals.
#3  0x00007f777750de51 in __GI___nptl_deallocate_tsd () at nptl_deallocate_tsd.c:74
        data = <optimized out>
        inner = <optimized out>
        level2 = 0x7f77767f9950
        idx = <optimized out>
        round = 0
        cnt = 0
        self = <optimized out>
        just_free = <optimized out>
        __value = <optimized out>
#4  __GI___nptl_deallocate_tsd () at nptl_deallocate_tsd.c:23
        self = <optimized out>
        just_free = <optimized out>
        round = <optimized out>
        cnt = <optimized out>
        idx = <optimized out>
        level2 = <optimized out>
        __value = <optimized out>
        inner = <optimized out>
        data = <optimized out>
        __value = <optimized out>
        level2 = <optimized out>
        __value = <optimized out>
#5  0x00007f7777510bf6 in start_thread (arg=<optimized out>) at pthread_create.c:454
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140730723210752, -1555500815657095516, 140151065908800, 25, 140151079635536, 0, 1479200209923583652, 1479202258555350692}, mask_was_saved = 0}}, priv = {
            pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#6  0x00007f7777595d40 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.
(gdb) thread 2
[Switching to thread 2 (Thread 0x7f7776808840 (LWP 3051156))]
#0  0x00007f7777b1f6bf in std::unordered_map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, int, std::hash<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::equal_to<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, int> > >::~unordered_map() () from /lib64/libXrdCl.so.3
(gdb) bt full
#0  0x00007f7777b1f6bf in std::unordered_map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, int, std::hash<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::equal_to<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, int> > >::~unordered_map() () from /lib64/libXrdCl.so.3
No symbol table info available.
#1  0x00007f77774c82e7 in __cxa_finalize (d=0x7f7777c87fe0) at cxa_finalize.c:83
        check = 299
        cxafn = 0x7f7777b1f690 <std::unordered_map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, int, std::hash<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::equal_to<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, int> > >::~unordered_map()>
        cxaarg = <optimized out>
        f = 0x55f2bb4106a0
        funcs = 0x55f2bb4102d0
        restart = <optimized out>
#2  0x00007f7777b194d7 in __do_global_dtors_aux () from /lib64/libXrdCl.so.3
No symbol table info available.
#3  0x00007ffe6cc437b0 in ?? ()
No symbol table info available.
#4  0x00007f7777ca12ce in _dl_fini () at dl-fini.c:142
        array = 0x7ffe6cc43440
        i = <optimized out>
        l = 0x7f7777c95000
        maps = 0x7ffe6cc43620
        i = 2
        l = <optimized out>
        nmaps = <optimized out>
        nloaded = <optimized out>
        ns = 0
        do_audit = <optimized out>
        __PRETTY_FUNCTION__ = "_dl_fini"
Backtrace stopped: frame did not save the PC

Some versioning info:

[root@client-0 /]# openssl --version
OpenSSL 3.2.2 4 Jun 2024 (Library: OpenSSL 3.2.2 4 Jun 2024)

[root@client-0 /]# xrdcp --version
v5.7.1

I'm missing some debuginfo btw; let me know @amadio if you need any additional info there

The stack trace above is incomplete, so it's not very useful to know where the problem is. Please try compiling everything with frame pointers and debugging info enabled to fix it.

That's what I suspected. I'll see if I can get some more useful in the stacktrace. For now to give some additional context, we get this error on:

ERROR with xrootd transfer for file 0/14043, full logs in /dev/shm/d10cf257-ab54-48e7-a2be-c35982d48354/014043
bash: line 1: 310421 Broken pipe             dd if=/tmp/testfile bs=1k 2> /dev/null
     310423 Done                    | ( dd bs=0 count=1 of=/dev/null 2> /dev/null; dd bs=14043 count=1 of=/dev/null 2> /dev/null; dd bs=1k count=1 2> /dev/null )
     310426 Segmentation fault      (core dumped) | XRD_LOGLEVEL=Dump xrdcp - root://ctaeos//eos/ctaeos/preprod/d10cf257-ab54-48e7-a2be-c35982d48354/0/014043 2> /dev/shm/d10cf257-ab54-48e7-a2be-c35982d48354/014043

Which generated the following dump xrd_segfault.dump

Please try with the latest version of XRootD (5.7.2), XRootD 5.6.1 has many bugs that have since been fixed.

mentioned in issue #1028 (closed)

Regarding this line:

{"epoch_time":1736241852.422857289,"local_time":"2025-01-07T10:24:12+0100","hostname":"tpsrv01-0","program":"cta-taped","log_level":"ERROR","pid":553,"tid":553,"message":"In Scheduler::reportRetrieveJobsBatch(): failed to report.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","fileId":4294977310,"reportType":"FailureReport","exceptionMSG":"In EOSReporter::AsyncQueryHandler::HandleResponse(): failed to XrdCl::FileSystem::Query() [ERROR] Server responded with an error: [3000] Unable to trigger workflow - no workflow defined for <workflow>.<event> [EINVAL] &mgm.pcmd=event&mgm.fid=2734&mgm.logid=cta&mgm.event=sync::retrieve_failed&mgm.workflow=default&mgm.path=/dummy_path&mgm.ruid=0&mgm.rgid=0&mgm.errmsg=; Invalid argument code:400 errNo:3000 status:1"}

It may simply be because we are trying to retrieve (or do any tape-related operation) on a file that has no workflow defined.

It may even be intentionally caused, as part of a system test that looks for some workflow related behaviour.

As such, I think this is probably unrelated to the segfaults.

Yes most likely; I think this even shows up in the tests that pass

The other segfault we are periodically getting is in the taped maintenance process. It fails with this log messages:

{"epoch_time":1737972756.175063849,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"ERROR","pid":373,"tid":373,"message":"In MaintenanceHandler::exceptionThrowingRunChild(): received an exception. Backtrace follows.","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected"}
{"epoch_time":1737972756.175145222,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":0,"traceFrame":"/lib64/libctacommon.so.0(cta::exception::Backtrace::Backtrace(bool)+0x6b) [0x7ff94ae383d1]"}
{"epoch_time":1737972756.175192213,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":1,"traceFrame":"/lib64/libctacommon.so.0(cta::exception::Exception::Exception(std::basic_string_view<char, std::char_traits<char> >, bool)+0x91) [0x7ff94ae393e9]"}
{"epoch_time":1737972756.175226788,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":2,"traceFrame":"/lib64/libctacommon.so.0(cta::exception::UserError::UserError(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, bool)+0x53) [0x7ff94ae3a8dd]"}
{"epoch_time":1737972756.175260295,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":3,"traceFrame":"/lib64/libctacatalogue.so.0(cta::catalogue::UserSpecifiedANonExistentTape::UserError(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, bool)+0x3e) [0x7ff95163a346]"}
{"epoch_time":1737972756.175296382,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":4,"traceFrame":"/lib64/libctacatalogue.so.0(cta::catalogue::RdbmsTapeCatalogue::modifyTapeState(cta::common::dataStructures::SecurityIdentity const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, cta::common::dataStructures::Tape::State const&, std::optional<cta::common::dataStructures::Tape::State> const&, std::optional<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > const&)+0x764) [0x7ff95162cefa]"}
{"epoch_time":1737972756.175332600,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":5,"traceFrame":"/lib64/libctacatalogue.so.0(+0x3e72b2) [0x7ff9516a42b2]"}
{"epoch_time":1737972756.175365718,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":6,"traceFrame":"/lib64/libctacatalogue.so.0(+0x3ec8e1) [0x7ff9516a98e1]"}
{"epoch_time":1737972756.175437793,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":7,"traceFrame":"/lib64/libctacatalogue.so.0(cta::catalogue::TapeCatalogueRetryWrapper::modifyTapeState(cta::common::dataStructures::SecurityIdentity const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, cta::common::dataStructures::Tape::State const&, std::optional<cta::common::dataStructures::Tape::State> const&, std::optional<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > const&)+0x7d) [0x7ff9516a4347]"}
{"epoch_time":1737972756.175475387,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":8,"traceFrame":"/lib64/libctaobjectstore.so.0(cta::objectstore::QueueCleanupRunner::runOnePass(cta::log::LogContext&)+0x1154) [0x7ff95267c8e6]"}
{"epoch_time":1737972756.175506106,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":9,"traceFrame":"/usr/bin/cta-taped() [0x4df177]"}
{"epoch_time":1737972756.175559578,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":10,"traceFrame":"/usr/bin/cta-taped() [0x4deb1c]"}
{"epoch_time":1737972756.175588778,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":11,"traceFrame":"/usr/bin/cta-taped() [0x4e36b9]"}
{"epoch_time":1737972756.175617462,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":12,"traceFrame":"/usr/bin/cta-taped() [0x4e2663]"}
{"epoch_time":1737972756.175648731,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":13,"traceFrame":"/usr/bin/cta-taped() [0x49c9a0]"}
{"epoch_time":1737972756.175677623,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":14,"traceFrame":"/usr/bin/cta-taped() [0x49c6e0]"}
{"epoch_time":1737972756.175706132,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":15,"traceFrame":"/usr/bin/cta-taped() [0x49c1a1]"}
{"epoch_time":1737972756.175754054,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":16,"traceFrame":"/usr/bin/cta-taped() [0x486f05]"}
{"epoch_time":1737972756.175784682,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":17,"traceFrame":"/usr/bin/cta-taped() [0x487ab8]"}
{"epoch_time":1737972756.175813470,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":18,"traceFrame":"/lib64/libc.so.6(+0x295d0) [0x7ff94a0b25d0]"}
{"epoch_time":1737972756.175842450,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":19,"traceFrame":"/lib64/libc.so.6(__libc_start_main+0x80) [0x7ff94a0b2680]"}
{"epoch_time":1737972756.175872275,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler","exceptionMessage":"Cannot modify the state of the tape V00101 because it does not exist or because a recent state change has been detected","traceFrameNumber":20,"traceFrame":"/usr/bin/cta-taped() [0x486975]"}
{"epoch_time":1737972756.181889607,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"ERROR","pid":373,"tid":373,"message":"In Agent::deleteAndUnregisterSelf: agent still owns objects. Here is a part of the list.","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","agentObject":"Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0","objects":"RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","startIndex":0,"endIndex":0,"totalObjects":1}
{"epoch_time":1737972756.184497556,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"CRIT","pid":373,"tid":373,"message":"In BackendPopulator::~BackendPopulator(): error deleting agent (cta::exception::Exception). Backtrace follows.","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195"}
{"epoch_time":1737972756.184563945,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":0,"traceFrame":"/lib64/libctacommon.so.0(cta::exception::Backtrace::Backtrace(bool)+0x6b) [0x7ff94ae383d1]"}
{"epoch_time":1737972756.184601864,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":1,"traceFrame":"/lib64/libctacommon.so.0(cta::exception::Exception::Exception(std::basic_string_view<char, std::char_traits<char> >, bool)+0x91) [0x7ff94ae393e9]"}
{"epoch_time":1737972756.184634152,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":2,"traceFrame":"/lib64/libctaobjectstore.so.0(cta::objectstore::Agent::AgentStillOwnsObjects::Exception(std::basic_string_view<char, std::char_traits<char> >, bool)+0x4c) [0x7ff9524f8440]"}
{"epoch_time":1737972756.184665362,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":3,"traceFrame":"/lib64/libctaobjectstore.so.0(cta::objectstore::Agent::removeAndUnregisterSelf(cta::log::LogContext&)+0x67c) [0x7ff9524f6994]"}
{"epoch_time":1737972756.184695661,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":4,"traceFrame":"/lib64/libctaobjectstore.so.0(cta::objectstore::BackendPopulator::~BackendPopulator()+0x2d3) [0x7ff9526470cf]"}
{"epoch_time":1737972756.184730833,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":5,"traceFrame":"/lib64/libctaobjectstore.so.0(cta::objectstore::BackendPopulator::~BackendPopulator()+0x27) [0x7ff952647537]"}
{"epoch_time":1737972756.184760156,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":6,"traceFrame":"/usr/bin/cta-taped() [0x4b767b]"}
{"epoch_time":1737972756.184788188,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":7,"traceFrame":"/usr/bin/cta-taped() [0x4b397b]"}
{"epoch_time":1737972756.184816069,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":8,"traceFrame":"/usr/bin/cta-taped() [0x4b8265]"}
{"epoch_time":1737972756.184843828,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":9,"traceFrame":"/usr/bin/cta-taped() [0x4dfe00]"}
{"epoch_time":1737972756.184871232,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":10,"traceFrame":"/usr/bin/cta-taped() [0x4deb1c]"}
{"epoch_time":1737972756.184898745,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":11,"traceFrame":"/usr/bin/cta-taped() [0x4e36b9]"}
{"epoch_time":1737972756.184929221,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":12,"traceFrame":"/usr/bin/cta-taped() [0x4e2663]"}
{"epoch_time":1737972756.184956998,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":13,"traceFrame":"/usr/bin/cta-taped() [0x49c9a0]"}
{"epoch_time":1737972756.184984529,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":14,"traceFrame":"/usr/bin/cta-taped() [0x49c6e0]"}
{"epoch_time":1737972756.185011999,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":15,"traceFrame":"/usr/bin/cta-taped() [0x49c1a1]"}
{"epoch_time":1737972756.185039753,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":16,"traceFrame":"/usr/bin/cta-taped() [0x486f05]"}
{"epoch_time":1737972756.185067197,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":17,"traceFrame":"/usr/bin/cta-taped() [0x487ab8]"}
{"epoch_time":1737972756.185094931,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":18,"traceFrame":"/lib64/libc.so.6(+0x295d0) [0x7ff94a0b25d0]"}
{"epoch_time":1737972756.185122743,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":19,"traceFrame":"/lib64/libc.so.6(__libc_start_main+0x80) [0x7ff94a0b2680]"}
{"epoch_time":1737972756.185176360,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":373,"tid":373,"message":"Stack trace","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","errorMessage":"In Agent::removeAndUnregisterSelf: agent (agentObject=Maintenance-cta-tpsrv02-0-373-20250127-10:58:22-0) still owns objects. Here's the first few: RetrieveRequest-Frontend-cta-frontend-0-239-20250127-10:58:05-0-30195","traceFrameNumber":20,"traceFrame":"/usr/bin/cta-taped() [0x486975]"}
{"epoch_time":1737972756.320643766,"local_time":"2025-01-27T11:12:36+0100","hostname":"cta-tpsrv02-0","program":"cta-taped","log_level":"INFO","pid":371,"tid":371,"message":"In signal handler, received SIGCHLD and propagations to other handlers","drive_name":"VDSTK02","instance":"CI","sched_backend":"ceph","signal":"Child exited","senderPID":373,"senderUID":0}

In particular the CRIT message: "In BackendPopulator::~BackendPopulator(): error deleting agent (cta::exception::Exception)

Looking at the timestamp, it seems to happen somewhere at the start of Step 14. here:

########################################################################################################
 13. Testing 'Tape state change from ACTIVE to DISABLED - queue preserved (1 copy only)
########################################################################################################
Setting up V00101 queue as ACTIVE...
1737972748 Waiting for tape V00101 state to change to ACTIVE: Seconds passed = 0
Requesting file prepare -s...
Checking that the request was queued...
Changing V00101 queue to DISABLED...
1737972749 Waiting for tape V00101 state to change to DISABLED: Seconds passed = 0
Checking that the request was not modified on the queue...
Queue preserved, as expected.
Cleaning up request and queues...
OK

########################################################################################################
 14. Testing 'Tape state change from DISABLED to ACTIVE - queue preserved (1 copy only)
########################################################################################################
Setting up V00101 queue as DISABLED...
1737972759 Waiting for tape V00101 state to change to DISABLED: Seconds passed = 0
Requesting file prepare -s...
Checking that the request was queued...
Changing V00101 queue to ACTIVE...
1737972760 Waiting for tape V00101 state to change to ACTIVE: Seconds passed = 0
Checking that the request was not modified on the queue...
Queue preserved, as expected.
Cleaning up request and queues...
OK

This is the same segfault as earlier in the issue actually: #1034 (comment 8975461)

Created this issue to look into the first part of the stack trace:

#1054 (closed)

Job logs were obtained from here: https://gitlab.cern.ch/cta/CTA/-/jobs/49934132

mentioned in issue #1054 (closed)

marked this issue as related to #1054 (closed)

marked this issue as related to #1057 (closed)

While some of the previous issues were resolved. We have some new sporadic failures. They are most likely unrelated to what was mentioned above as this time around we are reaching a timeout. See e.g.

Looking at the logs of https://gitlab.cern.ch/cta/CTA/-/jobs/50262844, it seems that the drive handler subprocess crashed at around the same time as the system test failed:

{"epoch_time":1738444859.653360818,"local_time":"2025-02-01T22:20:59+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":69927,"tid":69982,"message":"Tape mounted for read/write access","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","thread":"TapeWrite","tapeDrive":"VDSTK01","tapeVid":"V00101","mountId":"25","vo":"vo","tapePool":"ctasystest","mediaType":"LTO8","logicalLibrary":"VDSTK01","mountType":"ArchiveForUser","vendor":"vendor","capacityInBytes":12000000000000,"drive_Slot":"smc0","MCMountTime":0.010462,"mode":"RW"}
{"epoch_time":1738444859.682573525,"local_time":"2025-02-01T22:20:59+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":343,"tid":343,"message":"In signal handler, received SIGCHLD and propagations to other handlers","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","signal":"Child exited","senderPID":69927,"senderUID":0}
{"epoch_time":1738444859.682657454,"local_time":"2025-02-01T22:20:59+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":343,"tid":343,"message":"Handler received SIGCHILD. Propagating to all handlers.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","SubprocessName":"signalHandler"}
{"epoch_time":1738444859.682678040,"local_time":"2025-02-01T22:20:59+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":343,"tid":343,"message":"Propagated SIGCHILD.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","SubprocessName":"signalHandler"}
{"epoch_time":1738444859.682790551,"local_time":"2025-02-01T22:20:59+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":343,"tid":343,"message":"Drive subprocess crashed. Will spawn a new one.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","tapeDrive":"VDSTK01","subprocessPid":69927,"IfSignaled":true,"TermSignal":6,"CoreDump":128}
{"epoch_time":1738444859.682824932,"local_time":"2025-02-01T22:20:59+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":343,"tid":343,"message":"Tape session finished","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","tapeDrive":"VDSTK01","subprocessPid":69927,"IfSignaled":true,"TermSignal":6,"CoreDump":128,"Error_sessionKilled":1,"killSignal":6,"status":"failure"}

I could not find a stacktrace in the logs, but there is a coredump file of cta-tpsrv01-taped that could provide some info.

This is the coredump. It seems to have been caused by xrootd:

(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at pthread_kill.c:44
#1  0x00007ff17548dad3 in __pthread_kill_internal (signo=6, threadid=<optimized out>) at pthread_kill.c:78
#2  0x00007ff175440686 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x00007ff17542a833 in __GI_abort () at abort.c:79
#4  0x00007ff17542b170 in __libc_message (fmt=fmt@entry=0x7ff1755bd47f "*** %s ***: terminated\n") at ../sysdeps/posix/libc_fatal.c:150
#5  0x00007ff17551f87b in __GI___fortify_fail (msg=msg@entry=0x7ff1755bd425 "buffer overflow detected") at fortify_fail.c:24
#6  0x00007ff17551e1e6 in __GI___chk_fail () at chk_fail.c:28
#7  0x00007ff1737e4278 in strcpy (
    __src=0x7ff126ff8e78 "\273\376\374\332\377\334ݻ\357\252\356\372\333\334ݻ\377\376\336\276\373\254뿾\316\335\373\254\354\fݻ\377\376\336\276\373\254뿾\316\335\373\254\353\277\336\336\336\277\b\237\254\v\377ڜ\fݻ\377\376\336\276\373\254\353\277ͭ\357\272\316\362\246l\fݻ\376\374\332\377\334ݻ\357\252\356\372\333\334ݻ\377\376\336\276\373\254뿾\316\335\373\254\354\fݻ\377\376\336\276\373\254뿾\316\335\373\254\353\277\336\336\336\277\b\237\246l\v\377\332f\233\274\332\353ډ1\357\217\372Ќݻ\377\376\336\276\373\254\353\277ͭ\357\272\316\362\273\246\230\315ۿ\357ͯ\375\315۾\372\256ﭽ\315ۿ\377\355\353\357\272λ\373\354\355", <incomplete sequence \337>..., __dest=0x7ff126ff8d10 "") at /usr/include/bits/string_fortified.h:79
#8  XrdSecProtocolsss::getCredentials (this=0x7ff13c007bf0, parms=<optimized out>, einfo=0x7ff126ff90e0) at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdSecsss/XrdSecProtocolsss.cc:688
#9  0x00007ff175b048fc in XrdCl::XRootDTransport::GetCredentials (this=this@entry=0x7ff14002b690, credentials=@0x7ff126ff9998: 0x0, hsData=hsData@entry=0x7ff13c000df0, info=info@entry=0x7ff14002baf0)
    at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClXRootDTransport.cc:2662
#10 0x00007ff175b07365 in XrdCl::XRootDTransport::DoAuthentication (this=0x7ff14002b690, hsData=0x7ff13c000df0, info=0x7ff14002baf0) at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClXRootDTransport.cc:2417
#11 0x00007ff175afab93 in XrdCl::XRootDTransport::HandShakeMain (this=this@entry=0x7ff14002b690, handShakeData=handShakeData@entry=0x7ff13c000df0, channelData=...)
    at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClXRootDTransport.cc:586
#12 0x00007ff175afb2be in XrdCl::XRootDTransport::HandShake (this=0x7ff14002b690, handShakeData=0x7ff13c000df0, channelData=...) at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClXRootDTransport.cc:486
#13 0x00007ff175b77a59 in XrdCl::AsyncSocketHandler::HandleHandShake (this=this@entry=0x7ff14001f210, msg=std::unique_ptr<XrdCl::Message> = {...})
    at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClAsyncSocketHandler.cc:583
#14 0x00007ff175b7801b in XrdCl::AsyncSocketHandler::OnReadWhileHandshaking (this=0x7ff14001f210) at /usr/include/c++/11/bits/unique_ptr.h:172
#15 0x00007ff175b7867d in XrdCl::AsyncSocketHandler::EventRead (type=1 '\001', this=0x7ff14001f210) at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClAsyncSocketHandler.cc:248
#16 XrdCl::AsyncSocketHandler::EventRead (type=1 '\001', this=0x7ff14001f210) at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClAsyncSocketHandler.cc:234
#17 XrdCl::AsyncSocketHandler::Event (this=0x7ff14001f210, type=1 '\001') at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClAsyncSocketHandler.cc:224
#18 0x00007ff175af243a in (anonymous namespace)::SocketCallBack::Event (this=0x7ff14001fb70, chP=<optimized out>, cbArg=<optimized out>, evFlags=<optimized out>)
    at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdCl/XrdClPollerBuiltIn.cc:83
#19 0x00007ff17419bedf in XrdSys::IOEvents::Poller::CbkXeq (this=this@entry=0x7ff14000b980, cP=cP@entry=0x7ff14001fb90, events=1, eNum=<optimized out>, eTxt=<optimized out>)
    at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdSys/XrdSysIOEvents.cc:721
#20 0x00007ff17419c590 in XrdSys::IOEvents::PollE::Dispatch (this=this@entry=0x7ff14000b980, cP=0x7ff14001fb90, pollEv=<optimized out>)
    at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdSys/XrdSysIOEventsPollE.icc:274
#21 0x00007ff17419c798 in XrdSys::IOEvents::PollE::Begin (this=0x7ff14000b980, syncsem=<optimized out>, retcode=<optimized out>, eTxt=<optimized out>)
    at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdSys/XrdSysIOEventsPollE.icc:229
#22 0x00007ff1741992c1 in XrdSys::IOEvents::BootStrap::Start (parg=0x7ff14f7f26b0) at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdSys/XrdSysIOEvents.cc:149
#23 0x00007ff1741a10bc in XrdSysThread_Xeq (myargs=0x7ff14000a020) at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdSys/XrdSysPthread.cc:86
#24 0x00007ff17548bd22 in start_thread (arg=<optimized out>) at pthread_create.c:443
#25 0x00007ff175510d40 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

So looking at another recent failure, we can see the following:

#15 XrdSecProtocolsss::getCredentials (this=0x7f0010001230, parms=<optimized out>, einfo=0x7f00177eec60) at /usr/src/debug/xrootd-5.7.1-1.el9.x86_64/src/XrdSecsss/XrdSecProtocolsss.cc:688
        k = <optimized out>
        n = 200
        rrHdr = {<XrdSecsssRR_Hdr> = {ProtID = "sss", Pad = "\000", knSize = 0 '\000', EncType = 48 '0', static etBFish32 = 48 '0', KeyID = 72057597868990823}, keyName = '\000' <repeats 191 times>}
        rrDataHdr = {P = 0x7f0010014360}
        encKey = {static maxKLen = 128, static NameSZ = 192, static UserSZ = 128, static GrupSZ = 64, Data = {ID = 7449334094434926593, Flags = 0, Crt = 1734433252, Exp = 0, Opts = 0, Len = 32, 
            Val = "2\206\233\316\346\373|ϸ5\342\213&\"(b`\331>\245\265\255Z\243\330T\272Y\310uN`\377,*\255+\230\034-\255+\0207\302\356̯ⲯ\v\354\255ݬ\312\373\354\337\273\273\354\353\376ʬ\357\373\376\255\277\273\255ʉ\260\332\314\f\252\316\v\354\353\372\332\377\017\373\017\352п\260\272ܠ\316\314\356\336\322\302ۯ\357\372\356+/\334\334\001,*\374\332\374\342\262\312,,\312\355", <incomplete sequence \373\254>, 
            Name = "\316\375+,\352\242\302ھ\255++\354\255ݬ\312\373\354߲\302ڮۯ\342\262\375\315\300\022\302\357\357\332ҲB\302\377+/\362\302ڮ\257\375+,\332\312\315\354\322\352id\":981,\"tid\":1037,\"message\":\"In RAOManager::queryRAO(), successfully performed RAO.\",\"drive_name\":\"VDSTK01\",\"instance\":\"CI\",\"sched_bac", 
            User = "daemon\000ceph\",\"thread\":\"RecallTaskInjector\",\"tapeDrive\":\"VDSTK01\",\"mountId\":\"4\",\"vo\":\"vo\",\"tapePool\":\"ctasystest\",\"transactionId\"", 
            Grup = "daemon\000xecutedRAOAlgorithm\":\"linear\",\"vectorInitializationTime\":"}, static allUSR = 1, static anyUSR = 2, static anyGRP = 4, static usrGRP = 8, static noIPCK = 16, Next = 0x0}
...

Specifically, the User and Grup appear to contain part of the log messages for some reason. There seems to be something fishy going on with the string length. The null terminator of the string is present, but for some reason the string doesn't stop there.

The usage of strcpy here indeed seems to suggest that the problem lies in the incorrect termination of the string: https://github.com/xrootd/xrootd/blob/master/src/XrdSecsss/XrdSecProtocolsss.cc#L688

I have found one of these issues again in main (https://gitlab.cern.ch/cta/CTA/-/jobs/50763038), with the message:

"Uncaught exception of type \"cta::exception::Errnum\" in Thread.run(): >>>>In SocketPair::send(): failed to send(): Errno=90: Message too long"

{"epoch_time":1739222102.056272345,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"In Agent::removeAndUnregisterSelf(): Removed agent object.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","agentObject":"DriveProcess-VDSTK01-cta-tpsrv01-0-12104-20250210-22:14:55-0"}
{"epoch_time":1739222102.073122685,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"ERROR","pid":12104,"tid":12104,"message":"Aborting cta-taped on uncaught exception. Stack trace follows.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","exceptionMessage":"Uncaught exception of type \"cta::exception::Errnum\" in Thread.run(): >>>>In SocketPair::send(): failed to send():  Errno=90: Message too long\n/lib64/libctacommon.so.0(cta::exception::Backtrace::Backtrace(bool)+0x6b) [0x7fc980763949]\n/lib64/libctacommon.so.0(cta::exception::Exception::Exception(std::basic_string_view<char, std::char_traits<char> >, bool)+0x91) [0x7fc980764a11]\n/lib64/libctacommon.so.0(cta::exception::Errnum::Errnum(int, std::basic_string_view<char, std::char_traits<char> >)+0x77) [0x7fc98076439b]\n/lib64/libctacommon.so.0(cta::exception::Errnum::Errnum(std::basic_string_view<char, std::char_traits<char> >)+0x4d) [0x7fc9807645cb]\n/lib64/libctacommon.so.0(cta::exception::Errnum::throwOnMinusOne(long, std::basic_string_view<char, std::char_traits<char> >)+0x5c) [0x7fc980764842]\n/lib64/libctacommon.so.0(cta::server::SocketPair::send(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, cta::server::SocketPair::Side)+0x99) [0x7fc9807896df]\n/usr/bin/cta-taped() [0x4c98a9]\n/usr/bin/cta-taped() [0x506583]\n/usr/bin/cta-taped() [0x506835]\n/lib64/libctacommon.so.0(cta::threading::Thread::pthread_runner(void*)+0xb3) [0x7fc9807906df]\n/lib64/libc.so.6(+0x89d22) [0x7fc97fa46d22]\n/lib64/libc.so.6(+0x10ed40) [0x7fc97facbd40]\n<<<< End of uncaught exception"}
{"epoch_time":1739222102.073228476,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":0,"traceFrame":"/lib64/libctacommon.so.0(cta::exception::Backtrace::Backtrace(bool)+0x6b) [0x7fc980763949]"}
{"epoch_time":1739222102.073262248,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":1,"traceFrame":"/lib64/libctacommon.so.0(cta::exception::Exception::Exception(std::basic_string_view<char, std::char_traits<char> >, bool)+0x91) [0x7fc980764a11]"}
{"epoch_time":1739222102.073290177,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":2,"traceFrame":"/lib64/libctacommon.so.0(cta::threading::UncaughtExceptionInThread::Exception(std::basic_string_view<char, std::char_traits<char> >, bool)+0x4c) [0x7fc9807909fc]"}
{"epoch_time":1739222102.073317156,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":3,"traceFrame":"/lib64/libctacommon.so.0(cta::threading::Thread::wait()+0x13e) [0x7fc98079040e]"}
{"epoch_time":1739222102.073342778,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":4,"traceFrame":"/usr/bin/cta-taped() [0x507a19]"}
{"epoch_time":1739222102.073366691,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":5,"traceFrame":"/usr/bin/cta-taped() [0x502de4]"}
{"epoch_time":1739222102.073390453,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":6,"traceFrame":"/usr/bin/cta-taped() [0x500e63]"}
{"epoch_time":1739222102.073414096,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":7,"traceFrame":"/usr/bin/cta-taped() [0x4afa36]"}
{"epoch_time":1739222102.073437788,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":8,"traceFrame":"/usr/bin/cta-taped() [0x4abd33]"}
{"epoch_time":1739222102.073461049,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":9,"traceFrame":"/usr/bin/cta-taped() [0x4e46b9]"}
{"epoch_time":1739222102.073484397,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":10,"traceFrame":"/usr/bin/cta-taped() [0x4e3663]"}
{"epoch_time":1739222102.073507857,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":11,"traceFrame":"/usr/bin/cta-taped() [0x49d9a0]"}
{"epoch_time":1739222102.073534036,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":12,"traceFrame":"/usr/bin/cta-taped() [0x49d6e0]"}
{"epoch_time":1739222102.073567559,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":13,"traceFrame":"/usr/bin/cta-taped() [0x49d1a1]"}
{"epoch_time":1739222102.073591383,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":14,"traceFrame":"/usr/bin/cta-taped() [0x487f05]"}
{"epoch_time":1739222102.073614549,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":15,"traceFrame":"/usr/bin/cta-taped() [0x488ab8]"}
{"epoch_time":1739222102.073638034,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":16,"traceFrame":"/lib64/libc.so.6(+0x295d0) [0x7fc97f9e65d0]"}
{"epoch_time":1739222102.073662435,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":17,"traceFrame":"/lib64/libc.so.6(__libc_start_main+0x80) [0x7fc97f9e6680]"}
{"epoch_time":1739222102.073687477,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":12104,"tid":12104,"message":"Stack trace","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","traceFrameNumber":18,"traceFrame":"/usr/bin/cta-taped() [0x487975]"}
{"epoch_time":1739222102.083500498,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":313,"tid":313,"message":"In signal handler, received SIGCHLD and propagations to other handlers","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","signal":"Child exited","senderPID":12104,"senderUID":0}
{"epoch_time":1739222102.083591508,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":313,"tid":313,"message":"Handler received SIGCHILD. Propagating to all handlers.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","SubprocessName":"signalHandler"}
{"epoch_time":1739222102.083611441,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":313,"tid":313,"message":"Propagated SIGCHILD.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","SubprocessName":"signalHandler"}
{"epoch_time":1739222102.083674948,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":313,"tid":313,"message":"Drive subprocess exited. Will spawn a new one.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","tapeDrive":"VDSTK01","subprocessPid":12104,"exitCode":1}
{"epoch_time":1739222102.083710819,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":313,"tid":313,"message":"Tape session finished","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","tapeDrive":"VDSTK01","subprocessPid":12104,"exitCode":1,"killSignal":0}
{"epoch_time":1739222102.083763522,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":313,"tid":313,"message":"Propagated SIGCHILD.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","SubprocessName":"drive:VDSTK01"}
{"epoch_time":1739222102.083786883,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":313,"tid":313,"message":"Propagated SIGCHILD.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","SubprocessName":"maintenanceHandler"}
{"epoch_time":1739222102.083805119,"local_time":"2025-02-10T22:15:02+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"INFO","pid":313,"tid":313,"message":"Subprocess handler requested forking","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","SubprocessName":"drive:VDSTK01"}

Regardless of the solution, we should probably include the size of the message that we failed to transfer in the exception here:

https://gitlab.cern.ch/cta/CTA/-/blob/main/common/threading/SocketPair.cpp#L219

I still have a branch somewhere where I was looking into this; I'll see if I can find a fix today so that we can get rid of this.

This actually seems to be related to one of our recent commits:

971cf71e

Right before these messages we have:

{"epoch_time":1739222061.204070637,"local_time":"2025-02-10T22:14:21+0100","hostname":"cta-tpsrv01-0","program":"cta-taped","log_level":"ERROR","pid":8294,"tid":8294,"message":"In MigrationReportPacker::~MigrationReportPacker(), still pending jobs report.","drive_name":"VDSTK01","instance":"CI","sched_backend":"ceph","thread":"MainThread","tapeDrive":"VDSTK01","mountId":"12","vo":"vo_repack","tapePool":"ctasystest"}

But this message may exist only because now we are logging when we still have remaining "pending jobs" in MigrationReportPacker , while before we were ignoring and not logging it.

Anyway, we should try to log the thread ID here whenever we face an exception while joining a thread:

https://gitlab.cern.ch/cta/CTA/-/blob/main/common/threading/Thread.cpp#L58

mentioned in issue #1113

This issue has become quite bloated. Right now we are (seemingly) left with two major issues:

xrdcp segfaulting in our client pod (see #1113)
XRootD segfaulting in getCredentials() (see #1099)

So I'll be closing this issue in favour of the two issues above. The relevant discussions can continue there.

closed

Fix test client failing periodically

Designs

Child items ...

Activity

Fix test client failing periodically

Relates to

Activity