ATS 8.0.1 crash on NetAccept::do_blocking_accept()

[masaori335]

[ 0  ] libc-2.12.so       __libc_waitpid                          ( :undefined           ) 
[ 1  ] traffic_server     crash_logger_invoke                     ( Crash.cc:165         ) 
[ 2  ] libc-2.12.so       0x2b4b6d541570                          ( :undefined           ) 
[ 3  ] traffic_server     Mutex_lock                              ( I_Lock.h:408         ) 
[ 4  ] traffic_server     MutexLock                               ( I_Lock.h:506         ) 
[ 5  ] traffic_server     NetAccept::do_blocking_accept(EThread*) ( UnixNetAccept.cc:306 ) 
[ 6  ] traffic_server     NetAccept::acceptLoopEvent(int, Event*) ( UnixNetAccept.cc:524 ) 
[ 7  ] traffic_server     handleEvent                             ( I_Continuation.h:160 ) 
[ 8  ] traffic_server     EThread::execute()                      ( UnixEThread.cc:317   ) 
[ 9  ] traffic_server     spawn_thread_internal                   ( Thread.cc:85         ) 
[ 10 ] libpthread-2.12.so start_thread                            ( :undefined           )

[zwoop]

The full stack trace is

#0  0x00002b4b6d5bb8dd in waitpid () from /lib64/libc.so.6
No symbol table info available.
#1  0x00005605ae6b7d34 in crash_logger_invoke (signo=11, info=0x2b4b901e37b0, ctx=0x2b4b901e3680) at traffic_server/Crash.cc:165
        status = 0
#2  <signal handler called>
No symbol table info available.
#3  0x00005605ae8a37d8 in Mutex_lock (m=0x0, t=0x2b4bb500dbc0) at /usr/src/debug/bazinga-trafficserver-8.0.1/iocore/eventsystem/I_Lock.h:408
No locals.
#4  MutexLock::MutexLock (am=..., this=<optimized out>, t=<optimized out>) at /usr/src/debug/bazinga-trafficserver-8.0.1/iocore/eventsystem/I_Lock.h:506
No locals.
#5  NetAccept::do_blocking_accept (this=0x2b4b73772140, t=0x2b4bb500dbc0) at UnixNetAccept.cc:306
        lock = <optimized out>
        seriousness = -1
        now = 1545259351483331844
        res = <optimized out>
        loop = 1
        con = {
          _vptr$Connection = 0x5605aeb8c4f8 <vtable for Connection+16>,
          fd = -1,
          addr = {
            sa = {
              sa_family = 2,
              sa_data = "~c\262\313\350\245\000\000\000\000\000\000\000"
            },
            sin = {
              sin_family = 2,
              sin_port = 25470,
              sin_addr = {
                s_addr = 2783497138
              },
              sin_zero = "\000\000\000\000\000\000\000"
            },
            sin6 = {
              sin6_family = 2,
              sin6_port = 25470,
              sin6_flowinfo = 2783497138,
              sin6_addr = {
                __in6_u = {
                  __u6_addr8 = '\000' <repeats 15 times>,
                  __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0},
                  __u6_addr32 = {0, 0, 0, 0}
                }
              },
              sin6_scope_id = 0
            }
          },
          is_bound = false,
          is_connected = false,
          sock_type = 0
        }
        vc = <optimized out>
#6  0x00005605ae8a283b in NetAccept::acceptLoopEvent (this=0x2b4b73772140, event=<optimized out>, e=<optimized out>) at UnixNetAccept.cc:524
        t = 0x2b4bb500dbc0
#7  0x00005605ae8d03f4 in Continuation::handleEvent (this=<optimized out>, event=1, data=0x67) at ./I_Continuation.h:160
No locals.
#8  EThread::execute (this=0x2b4bb500dbc0) at UnixEThread.cc:317
No locals.
#9  0x00005605ae8cef0c in spawn_thread_internal (a=0x2b4b73768500) at Thread.cc:85
        p = 0x2b4b73768500
#10 0x00002b4b6d8aaaa1 in start_thread () from /lib64/libpthread.so.0

But, not sure this makes a lot of sense...

[scw00]

Can you please print errno ?

[oknet]

just remove the line:

306         SCOPED_MUTEX_LOCK(lock, action_->mutex, t);

ProtocolProbeSessionAccept does not have a mutex.

And you can found these code from UnixNetVConnection::acceptEvent():

1090   if (action_.continuation->mutex != nullptr) {
1091     MUTEX_TRY_LOCK(lock3, action_.continuation->mutex, t);
1092     if (!lock3.is_locked()) {
1093       ink_release_assert(0);
1094     }
1095     action_.continuation->handleEvent(NET_EVENT_ACCEPT, this);
1096   } else {
1097     action_.continuation->handleEvent(NET_EVENT_ACCEPT, this);
1098   }

The vc->action_ is copied from na->action_ within NetAccept::do_blocking_accept()

347     vc->submit_time = Thread::get_hrtime();
348     vc->action_     = *action_;
349     vc->set_is_transparent(opt.f_inbound_transparent);

[masaori335]

On frame 5, action_ is NetAcceptAction and action_.continuation is ProtocolProbeSessionAccept.

(gdb) p *action_.m_ptr
$5 = {<Action> = {_vptr$Action = 0x5605aeb8d078 <vtable for NetAcceptAction+16>, continuation = 0x2b4b8344cda0, mutex = {m_ptr = 0x0},
    cancelled = 0}, <RefCountObj> = {<ForceVFPTToTop> = {_vptr$ForceVFPTToTop = 0x5605aeb8d0a0 <vtable for NetAcceptAction+56>}, m_refcount = 1},
  server = 0x2b4b73772180}
(gdb) p *action_.m_ptr->continuation
$6 = {<force_VFPT_to_top> = {_vptr$force_VFPT_to_top = 0x5605aeb8bce0 <vtable for ProtocolProbeSessionAccept+16>}, handler = &virtual table offset 24,
  mutex = {m_ptr = 0x0}, link = {<SLink<Continuation>> = {next = 0x0}, prev = 0x0}, control_flags = {raw_flags = 0}}

And NetAccept::do_blocking_accept() is going to call action_->continuation->handleEvent().

306         SCOPED_MUTEX_LOCK(lock, action_->mutex, t);
307         action_->continuation->handleEvent(EVENT_ERROR, (void *)(intptr_t)res);

Should we do null check and lock the mutex of action_->continuation instead of just removing the line 306?

[masaori335]

@scwoo Unfortunately, I could not access memory of the errno.

[scw00]

The ProtocolProbeSessionAccept should not have the mutex. Since it shared with multi-thread. But I'm really wonder to known which errno cause this error.

Even if remove this line. It also crash see

int
ProtocolProbeSessionAccept::mainEvent(int event, void *data)
{
  if (event == NET_EVENT_ACCEPT) {
    ink_assert(data);

    VIO *vio;
    NetVConnection *netvc          = (NetVConnection *)data;
    ProtocolProbeTrampoline *probe = new ProtocolProbeTrampoline(this, netvc->mutex, nullptr, nullptr);

    // XXX we need to apply accept inactivity timeout here ...

    if (!probe->reader->is_read_avail_more_than(0)) {
      Debug("http", "probe needs data, read..");
      vio = netvc->do_io_read(probe, BUFFER_SIZE_FOR_INDEX(ProtocolProbeTrampoline::buffer_size_index), probe->iobuf);
      vio->reenable();
    } else {
      Debug("http", "probe already has data, call ioComplete directly..");
      vio = netvc->do_io_read(nullptr, 0, nullptr);
      probe->ioCompletionEvent(VC_EVENT_READ_COMPLETE, (void *)vio);
    }
    return EVENT_CONT;
  }

  ink_abort("Protocol probe received a fatal error: errno = %d", -((int)(intptr_t)data));
  return EVENT_CONT;
}

It dose not handle EVENT_ERROR.

[vmamidi]

is this happening because of changes to event system? #2541

[oknet]

@vmamidi No, it is not.

The following three git blame commands show that the crash issue was born with ATS.

git blame a165134 iocore/net/UnixNetAccept.cc

a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 378)     if ((res = server.accept(&vc->con)) < 0) {
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 379)     Lerror:
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 380)       int seriousness = accept_error_seriousness(res);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 381)       if (seriousness >= 0) {   // not so bad
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 382)         if (!seriousness)       // bad enough to warn about
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 383)           check_transient_accept_error(res);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 384)         safe_delay(NET_THROTTLE_DELAY);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 385)         return 0;
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 386)       }
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 387)       if (!action_->cancelled) {
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 388)         MUTEX_LOCK(lock, action_->mutex, t);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 389)         action_->continuation->handleEvent(EVENT_ERROR, (void *) res);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 390)         MUTEX_UNTAKE_LOCK(action_->mutex, t);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 391)         IOCORE_MachineFatal("accept thread received fatal error: errno = %d", errno);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 392)       }
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 393)       return -1;
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 394)     }

git blame a165134 proxy/http2/HttpAccept.h

a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 48) /**
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 49)   The continuation mutex is NULL to allow parellel accepts in NT. The
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 50)   only state used by the handler is attr and backdoor which is setup
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 51)   at the beginning of time and never changed. No state is recorded by
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 52)   the handler. So a NULL mutex is safe.
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 53) 
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 54) */
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 55) inline
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 56) HttpAccept::HttpAccept(int aattr, bool abackdoor)
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 57)   :
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 58) Continuation(NULL),
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 59) backdoor(abackdoor),
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 60) attr(aattr)
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 61) {
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 62)   SET_HANDLER(&HttpAccept::mainEvent);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 63)   return;
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 64) }

git blame a165134 proxy/http2/HttpAccept.cc

a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  80)   } else {
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  81)     /////////////////
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  82)     // EVENT_ERROR //
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  83)     /////////////////
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  84)     if (((long) data) == -ECONNABORTED) {
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  85)       /////////////////////////////////////////////////
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  86)       // Under Solaris, when accept() fails and sets //
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  87)       // errno to EPROTO, it means the client has    //
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  88)       // sent a TCP reset before the connection has  //
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  89)       // been accepted by the server...  Note that   //
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  90)       // in 2.5.1 with the Internet Server Supplement//
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  91)       // and also in 2.6 the errno for this case has //
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  92)       // changed from EPROTO to ECONNABORTED.        //
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  93)       /////////////////////////////////////////////////
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  94) 
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  95)       // FIX: add time to user_agent_hangup
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  96)       HTTP_SUM_DYN_STAT(http_ua_msecs_counts_errors_pre_accept_hangups_stat, 0);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  97)     }
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  98)     MachineFatal("HTTP accept received fatal error: errno = %d", -((int) data));
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000  99)     return (EVENT_CONT);
a1651345d1 (Andrew Hsu 2009-10-29 23:01:48 +0000 100)   }

The initial committed code shows:

• The mutex of HttpAccept is NULL to allow parallel accepts.
• HttpAccept will call MachineFatal if the event is not NET_EVENT_ACCEPT.

So remove the Line 306 of Netaccept.cc is ok,
ATS still crashed by MachineFatal /ink_abort but it is by design.

@masaori335

Todo:

• Delete the Line 306 of Netaccept.cc,
• Waiting for the crash again,
• Collect the message of ink_abort so that we can get the value of errno.

[vmamidi]

@oknet i understand what you are saying but it doesn't make sense what triggered this crash in 8.x?