[TS-1330] Logging related segfault in 3.2.0

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 3.2.0
• Fix Version/s: 3.3.5
• Component/s: Logging
• Labels: A crash

Environment

ATS 3.2.0 on RHEL 6.2 64-bit

• Assignee: Yunkai Zhang
• Reporter: David Carlin
• Created: 03/Jul/12 00:21
• Updated: 09/Aug/13 14:34
• Resolved: 02/Aug/13 04:35

Description

I observed the following crash once on one of our ATS boxes - possibly related to TS-1240

Jul 2 13:56:56 l2 traffic_server[25853]:

{0x2b0a391e1700} ERROR: [SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_SYSCALL, underlying IO error: Connection reset by peer
Jul 2 13:59:56 l2 kernel: [ET_NET 1][25855]: segfault at c ip 000000000058e083 sp 00002b0a2982b740 error 6
Jul 2 13:59:56 l2 kernel: [ET_NET 3][25857]: segfault at 84 ip 000000000058e083 sp 00002b0a29a31740 error 6 in traffic_server[400000+340000]
Jul 2 13:59:56 l2 kernel: in traffic_server[400000+340000]
Jul 2 14:02:59 l2 traffic_cop[25901]: (test) read timeout [180000 ]
Jul 2 14:02:59 l2 traffic_cop[25901]: server heartbeat failed [1]
Jul 2 14:03:08 l2 traffic_manager[25826]: {0x7f3f088607e0} FATAL: [LocalManager::pollMgmtProcessServer] Error in read (errno: 104)
Jul 2 14:03:09 l2 traffic_manager[25826]: {0x7f3f088607e0} FATAL: (last system error 104: Connection reset by peer)
Jul 2 14:03:09 l2 traffic_cop[25901]: cannot find traffic_server [1]
Jul 2 14:03:09 l2 traffic_manager[25826]: {0x7f3f088607e0} ERROR: [LocalManager::sendMgmtMsgToProcesses] Error writing message
Jul 2 14:03:09 l2 traffic_manager[25826]: {0x7f3f088607e0} ERROR: (last system error 32: Broken pipe)
Jul 2 14:03:12 l2 traffic_cop[25901]: cop received child status signal [25826 35584]
Jul 2 14:03:12 l2 traffic_cop[25901]: traffic_manager not running, making sure traffic_server is dead
Jul 2 14:03:12 l2 traffic_cop[25901]: spawning traffic_manager
Jul 2 14:03:13 l2 traffic_manager[18267]: NOTE: — Manager Starting —
Jul 2 14:03:13 l2 traffic_manager[18267]: NOTE: Manager Version: Apache Traffic Server - traffic_manager - 3.2.0 - (build # 52518 on Jun 25 2012 at 18:22:12)
Jul 2 14:03:13 l2 traffic_manager[18267]: {0x7fe63de3f7e0} STATUS: opened /home/y/logs/trafficserver/manager.log
Jul 2 14:03:15 l2 traffic_server[18322]: NOTE: — Server Starting —
Jul 2 14:03:15 l2 traffic_server[18322]: NOTE: Server Version: Apache Traffic Server - traffic_server - 3.2.0 - (build # 52518 on Jun 25 2012 at 18:22:31)
Jul 2 14:03:15 l2 traffic_server[18322]: {0x2b77573ab860} STATUS: opened /home/y/logs/trafficserver/diags.log
Jul 2 14:03:15 l2 traffic_server[18322]: {0x2b77573ab860} ERROR: Cannot insert duplicate!
Jul 2 14:03:22 l2 traffic_cop[25901]: server heartbeat succeeded


[Jul 2 13:56:56.304] Server {0x2b0a391e1700}

ERROR: [SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_SYSCALL, underlying IO error: Connection reset by peer
NOTE: Traffic Server received Sig 11: Segmentation fault
NOTE: Traffic Server received Sig 11: Segmentation fault
/home/y/bin/traffic_server - STACK TRACE:
/home/y/bin/traffic_server - STACK TRACE:
/lib64/libpthread.so.0[0x3b54e0f4a0]
/lib64/libpthread.so.0[0x3b54e0f4a0]
/home/y/bin/traffic_server(_ZN9LogBuffer14checkout_writeEPmm+0x153)[0x58e083]
/home/y/bin/traffic_server(_ZN9LogObject15_checkout_writeEPmm+0xa8)[0x5a64c8]
/home/y/bin/traffic_server(_ZN9LogObject3logEP9LogAccessPc+0x2f0)[0x5a7e30]
/home/y/bin/traffic_server(_ZN9LogBuffer14checkout_writeEPmm+0x153)[0x58e083]
/home/y/bin/traffic_server(_ZN9LogObject15_checkout_writeEPmm+0xa8)[0x5a64c8]
/home/y/bin/traffic_server(_ZN9LogObject3logEP9LogAccessPc+0x2f0)[0x5a7e30]
/home/y/bin/traffic_server(_ZN3Log6accessEP9LogAccess+0x146)[0x58f506]
/home/y/bin/traffic_server(_ZN6HttpSM12update_statsEv+0x630)[0x526c50]
/home/y/bin/traffic_server(_ZN3Log6accessEP9LogAccess+0x146)[0x58f506]
/home/y/bin/traffic_server(_ZN6HttpSM9kill_thisEv+0x928)[0x52b548]
/home/y/bin/traffic_server(_ZN6HttpSM12update_statsEv+0x630)[0x526c50]
/home/y/bin/traffic_server(_ZN6HttpSM9kill_thisEv+0x928)[0x52b548]
/home/y/bin/traffic_server(_ZN6HttpSM12main_handlerEiPv+0x198)[0x52b868]
/home/y/bin/traffic_server(_ZN10HttpTunnel12main_handlerEiPv+0xde)[0x56c3ee]
/home/y/bin/traffic_server[0x6736a1]
/home/y/bin/traffic_server(_ZN6HttpSM12main_handlerEiPv+0x198)[0x52b868]
/home/y/bin/traffic_server(_Z15write_to_net_ioP10NetHandlerP18UnixNetVConnectionP7EThread+0x847)[0x675517]
/home/y/bin/traffic_server[0x672f81]
/home/y/bin/traffic_server(_ZN10NetHandler12mainNetEventEiP5Event+0x286)[0x66df96]
/home/y/bin/traffic_server[0x676ad5]
/home/y/bin/traffic_server(_ZN7EThread13process_eventEP5Eventi+0xb4)[0x696b14]
/home/y/bin/traffic_server(_ZN10NetHandler12mainNetEventEiP5Event+0x1f2)[0x66df02]
/home/y/bin/traffic_server(_ZN7EThread13process_eventEP5Eventi+0xb4)[0x696b14]
/home/y/bin/traffic_server(_ZN7EThread7executeEv+0x4c3)[0x6974a3]
/home/y/bin/traffic_server[0x695ae2]
/lib64/libpthread.so.0[0x3b54e077f1]
/lib64/libc.so.6(clone+0x6d)[0x3b54ae5ccd]
/home/y/bin/traffic_server(_ZN7EThread7executeEv+0x4c3)[0x6974a3]
/home/y/bin/traffic_server[0x695ae2]
/lib64/libpthread.so.0[0x3b54e077f1]
/lib64/libc.so.6(clone+0x6d)[0x3b54ae5ccd]
[Jul 2 14:03:08.684] Manager

{0x7f3f088607e0} FATAL: [LocalManager::pollMgmtProcessServer] Error in read (errno: 104)
[Jul 2 14:03:09.213] Manager {0x7f3f088607e0}

FATAL: (last system error 104: Connection reset by peer)
[Jul 2 14:03:09.213] Manager

{0x7f3f088607e0} NOTE: [LocalManager::mgmtShutdown] Executing shutdown request.
[Jul 2 14:03:09.213] Manager {0x7f3f088607e0}

NOTE: [LocalManager::processShutdown] Executing process shutdown request.
[Jul 2 14:03:09.496] Manager

{0x7f3f088607e0} ERROR: [LocalManager::sendMgmtMsgToProcesses] Error writing message
[Jul 2 14:03:09.496] Manager {0x7f3f088607e0}

ERROR: (last system error 32: Broken pipe)

[example_alarm_bin.sh] sent alarm: l2.ycs.uls.yahoo.com [Mon Jul 2 14:03:09 2012] The TS-TM connection is broken for some reason. Either restart TS and TM or correct this error for TM to display TS statistics correctly

Issue Links

• duplicates: TS-2067 Core at LogBuffer::checkout_write()