//The log is to detect bursting traffic that
// caused write transaction avg. latency to spike.
VOID
VmDirWtxnOutstandingInc()
{
BOOLEAN bLock = FALSE;
double stats_peroid_ms = 0.0;
double offered_rate = 0.0;
VMDIR_LOCK_MUTEX(bLock, g_w_txns_mutex);
if (g_w_txns_outstanding == 0)
{
g_start_ts_ms = VmDirGetTimeInMilliSec();
g_stats_cnt = 0;
}
g_w_txns_outstanding++;
g_stats_cnt++;
if (g_w_txns_outstanding >= g_w_txns_outstanding_thresh && g_stats_cnt >= g_w_txns_outstanding_thresh)
{
stats_peroid_ms = (double)(VmDirGetTimeInMilliSec() - g_start_ts_ms);
if (stats_peroid_ms > 1) //avoid float point division overflow
{
offered_rate = (double)g_stats_cnt * 1000.0 / stats_peroid_ms;
VMDIR_LOG_INFO(VMDIR_LOG_MASK_ALL, "%s: write transactions outstanding %d for peroid %.2g ms with offered rate %.3g on %d write requests",
__func__, g_w_txns_outstanding, stats_peroid_ms, offered_rate, g_stats_cnt);
}
g_stats_cnt = 0;
g_start_ts_ms = VmDirGetTimeInMilliSec();
}
VMDIR_UNLOCK_MUTEX(bLock, g_w_txns_mutex);
}
static
VOID
_VmDirCollectBindSuperLog(
PVDIR_CONNECTION pConn,
PVDIR_OPERATION pOp
)
{
DWORD dwError = 0;
pConn->SuperLogRec.iEndTime = VmDirGetTimeInMilliSec();
if (pOp->reqDn.lberbv.bv_val) // TODO, for failed SASL bind scenario, we need DN/UPN a well.
{
dwError = VmDirAllocateStringA(pOp->reqDn.lberbv.bv_val, &(pConn->SuperLogRec.pszBindID));
BAIL_ON_VMDIR_ERROR(dwError);
}
VmDirLogOperation(gVmdirGlobals.pLogger, LDAP_REQ_BIND, pConn, pOp->ldapResult.errCode);
//
// Flush times once we log.
//
pConn->SuperLogRec.iStartTime = pConn->SuperLogRec.iEndTime = 0;
cleanup:
return;
error:
VMDIR_LOG_ERROR(VMDIR_LOG_MASK_ALL, "%s failed, error code %d", __FUNCTION__, dwError);
goto cleanup;
}
static
int
WriteBerOnSocket(
VDIR_CONNECTION * conn,
BerElement * ber )
{
long retVal = 0;
uint64_t iWriteStartTimeInMSec = 0;
iWriteStartTimeInMSec = VmDirGetTimeInMilliSec();
while( VmDirGetTimeInMilliSec() - iWriteStartTimeInMSec <
(MAX_NUM_SECONDS_OF_SOCK_WRITE_RETRIES * MSECS_IN_SECOND) )
{
if ( (retVal = ber_flush2( conn->sb, ber, LBER_FLUSH_FREE_NEVER )) == 0 )
{
break;
}
#ifdef _WIN32
// in ber_flush2 (liblber) call, sock_errset() call WSASetLastError()
errno = WSAGetLastError();
#endif
if ( errno == EWOULDBLOCK || errno == EAGAIN )
{
continue;
}
}
if (retVal != 0)
{
VMDIR_LOG_ERROR( VMDIR_LOG_MASK_ALL, "WriteBerOnSocket: ber_flush2() call failed with errno = %d.", errno );
}
return retVal;
}
DWORD
VmDirConditionTimedWait(
PVMDIR_COND pCondition,
PVMDIR_MUTEX pMutex,
DWORD dwMilliseconds
)
{
DWORD dwError = ERROR_SUCCESS;
struct timespec ts = {0};
uint64_t iTimeInMSec = 0;
if ( ( pCondition == NULL )
||
( pCondition->bInitialized == FALSE )
||
( pMutex == NULL )
||
( pMutex->bInitialized == FALSE )
)
{
dwError = ERROR_INVALID_PARAMETER;
BAIL_ON_VMDIR_ERROR(dwError);
}
iTimeInMSec = dwMilliseconds + VmDirGetTimeInMilliSec();
ts.tv_sec = iTimeInMSec / MSECS_PER_SEC;
ts.tv_nsec = (iTimeInMSec % MSECS_PER_SEC) * NSECS_PER_MSEC;
dwError = pthread_cond_timedwait(
&(pCondition->cond),
&(pMutex->critSect),
&ts
);
BAIL_ON_VMDIR_ERROR(dwError);
error:
return dwError;
}
DWORD
VmDirRWLockWriteLock(
PVMDIR_RWLOCK pLock,
DWORD dwMilliSec
)
{
#ifdef __APPLE__
return VMDIR_ERROR_OPERATION_NOT_PERMITTED;
#else
DWORD dwError = 0;
if (!pLock || !pLock->bInitialized)
{
dwError = VMDIR_ERROR_INVALID_PARAMETER;
BAIL_ON_VMDIR_ERROR(dwError);
}
if (dwMilliSec)
{
struct timespec ts = {0};
uint64_t iTimeInMSec = 0;
iTimeInMSec = dwMilliSec + VmDirGetTimeInMilliSec();
ts.tv_sec = iTimeInMSec / MSECS_PER_SEC;
ts.tv_nsec = (iTimeInMSec % MSECS_PER_SEC) * NSECS_PER_MSEC;
dwError = pthread_rwlock_timedwrlock(&pLock->lock, &ts);
BAIL_ON_VMDIR_ERROR(dwError);
}
else
{
dwError = pthread_rwlock_wrlock(&pLock->lock);
BAIL_ON_VMDIR_ERROR(dwError);
}
error:
return dwError;
#endif
}
static
int
BindListenOnPort(
#ifndef _WIN32
sa_family_t addr_type,
size_t addr_size,
#else
short addr_type,
int addr_size,
#endif
void *pServ_addr,
ber_socket_t *pSockfd
)
{
#define LDAP_PORT_LISTEN_BACKLOG 128
int optname = 0;
int retVal = LDAP_SUCCESS;
int retValBind = 0;
PSTR pszLocalErrMsg = NULL;
int on = 1;
#ifdef _WIN32
DWORD sTimeout = 0;
int reTries = 0;
#else
struct timeval sTimeout = {0};
#endif
*pSockfd = -1;
*pSockfd = socket(addr_type, SOCK_STREAM, 0);
if (*pSockfd < 0)
{
#ifdef _WIN32
errno = WSAGetLastError();
#endif
retVal = LDAP_OPERATIONS_ERROR;
BAIL_ON_VMDIR_ERROR_WITH_MSG( retVal, pszLocalErrMsg,
"%s: socket() call failed with errno: %d", __func__, errno );
}
#ifdef _WIN32
optname = SO_EXCLUSIVEADDRUSE;
#else
optname = SO_REUSEADDR;
#endif
if (setsockopt(*pSockfd, SOL_SOCKET, optname, (const char *)(&on), sizeof(on)) < 0)
{
#ifdef _WIN32
errno = WSAGetLastError();
#endif
retVal = LDAP_OPERATIONS_ERROR;
BAIL_ON_VMDIR_ERROR_WITH_MSG( retVal, pszLocalErrMsg,
"%s: setsockopt() call failed with errno: %d", __func__, errno );
}
on = 1; // turn on TCP_NODELAY below
if (setsockopt(*pSockfd, IPPROTO_TCP, TCP_NODELAY, (const char *)(&on), sizeof(on) ) < 0)
{
#ifdef _WIN32
errno = WSAGetLastError();
#endif
retVal = LDAP_OPERATIONS_ERROR;
BAIL_ON_VMDIR_ERROR_WITH_MSG( retVal, pszLocalErrMsg,
"%s: setsockopt() TCP_NODELAY call failed with errno: %d", __func__, errno );
}
if (addr_type == AF_INET6)
{
#ifdef _WIN32
if (setsockopt(*pSockfd, IPPROTO_IPV6, IPV6_V6ONLY, (const char *)(&on), sizeof(on) ) < 0)
{
errno = WSAGetLastError();
#else
if (setsockopt(*pSockfd, SOL_IPV6, IPV6_V6ONLY, (const char *)(&on), sizeof(on) ) < 0)
{
#endif
retVal = LDAP_OPERATIONS_ERROR;
BAIL_ON_VMDIR_ERROR_WITH_MSG( retVal, pszLocalErrMsg,
"%s: setsockopt() IPV6_V6ONLY call failed with errno: %d", __func__, errno );
}
}
if (gVmdirGlobals.dwLdapRecvTimeoutSec > 0)
{
#ifdef _WIN32
sTimeout = gVmdirGlobals.dwLdapRecvTimeoutSec*1000;
#else
sTimeout.tv_sec = gVmdirGlobals.dwLdapRecvTimeoutSec;
sTimeout.tv_usec = 0;
#endif
if (setsockopt(*pSockfd, SOL_SOCKET, SO_RCVTIMEO, (const char*) &sTimeout, sizeof(sTimeout)) < 0)
{
#ifdef _WIN32
errno = WSAGetLastError();
#endif
retVal = LDAP_OPERATIONS_ERROR;
BAIL_ON_VMDIR_ERROR_WITH_MSG( retVal, pszLocalErrMsg,
"%s: setsockopt() SO_RCVTIMEO failed, errno: %d", __func__, errno );
}
}
retValBind = bind(*pSockfd, (struct sockaddr *) pServ_addr, addr_size);
#ifdef _WIN32
// Add retry logic per PR 1347783
reTries = 0;
while (retValBind != 0 && reTries < MAX_NUM_OF_BIND_PORT_RETRIES)
{
errno = WSAGetLastError();
if (errno != WSAEADDRINUSE)
{
break;
}
reTries++;
VMDIR_LOG_WARNING( VMDIR_LOG_MASK_ALL, "%s: bind() call failed with errno: %d, re-trying (%d)",
__func__, errno, reTries);
VmDirSleep(1000);
retValBind = bind(*pSockfd, (struct sockaddr *) pServ_addr, addr_size);
}
#endif
if (retValBind != 0)
{
retVal = LDAP_OPERATIONS_ERROR;
//need to free socket ...
BAIL_ON_VMDIR_ERROR_WITH_MSG( retVal, pszLocalErrMsg,
"%s: bind() call failed with errno: %d", __func__, errno );
}
if (listen(*pSockfd, LDAP_PORT_LISTEN_BACKLOG) != 0)
{
#ifdef _WIN32
errno = WSAGetLastError();
#endif
retVal = LDAP_OPERATIONS_ERROR;
BAIL_ON_VMDIR_ERROR_WITH_MSG( retVal, pszLocalErrMsg,
"%s: listen() call failed with errno: %d", __func__, errno );
}
cleanup:
VMDIR_SAFE_FREE_MEMORY(pszLocalErrMsg);
return retVal;
error:
if (*pSockfd >= 0)
{
tcp_close(*pSockfd);
*pSockfd = -1;
}
VMDIR_LOG_ERROR(VMDIR_LOG_MASK_ALL, VDIR_SAFE_STRING(pszLocalErrMsg));
goto cleanup;
}
/*
* We own pConnection and delete it when done.
*/
static
DWORD
ProcessAConnection(
PVOID pArg
)
{
VDIR_CONNECTION *pConn = NULL;
int retVal = LDAP_SUCCESS;
ber_tag_t tag = LBER_ERROR;
ber_len_t len = 0;
BerElement * ber = NULL;
ber_int_t msgid = -1;
PVDIR_OPERATION pOperation = NULL;
int reTries = 0;
BOOLEAN bDownOpThrCount = FALSE;
PVDIR_CONNECTION_CTX pConnCtx = NULL;
// increment operation thread counter
retVal = VmDirSyncCounterIncrement(gVmdirGlobals.pOperationThrSyncCounter);
BAIL_ON_VMDIR_ERROR(retVal);
bDownOpThrCount = TRUE;
pConnCtx = (PVDIR_CONNECTION_CTX)pArg;
assert(pConnCtx);
retVal = NewConnection(pConnCtx->sockFd, &pConn, pConnCtx->pSockbuf_IO);
if (retVal != LDAP_SUCCESS)
{
VMDIR_LOG_ERROR( VMDIR_LOG_MASK_ALL, "%s: NewConnection [%d] failed with error: %d",
__func__, pConnCtx->sockFd, retVal);
goto error;
}
while (TRUE)
{
if (VmDirdState() == VMDIRD_STATE_SHUTDOWN)
{
goto cleanup;
}
ber = ber_alloc();
assert( ber != NULL);
/* An LDAP request message looks like:
* LDAPMessage ::= SEQUENCE {
* messageID MessageID,
* protocolOp CHOICE {
* bindRequest BindRequest,
* unbindRequest UnbindRequest,
* searchRequest SearchRequest,
* ... },
* controls [0] Controls OPTIONAL }
*/
// reset retry count
reTries = 0;
// Read complete LDAP request message (tag, length, and real message).
while( reTries < MAX_NUM_OF_SOCK_READ_RETRIES )
{
if ((tag = ber_get_next( pConn->sb, &len, ber )) == LDAP_TAG_MESSAGE )
{
break;
}
#ifdef _WIN32
// in ber_get_next (liblber) call, sock_errset() call WSASetLastError()
errno = WSAGetLastError();
if ( errno == EWOULDBLOCK || errno == EAGAIN || errno == WSAETIMEDOUT)
#else
if ( errno == EWOULDBLOCK || errno == EAGAIN)
#endif
{
if (gVmdirGlobals.dwLdapRecvTimeoutSec > 0 && ber->ber_len == 0)
{
VMDIR_LOG_INFO( LDAP_DEBUG_CONNS,
"%s: disconnecting peer (%s), idle > %d seconds",
__func__, pConn->szClientIP, gVmdirGlobals.dwLdapRecvTimeoutSec);
retVal = LDAP_NOTICE_OF_DISCONNECT;
BAIL_ON_VMDIR_ERROR( retVal );
}
//This may occur when not all data have recieved - set to EAGAIN/EWOULDBLOCK by ber_get_next,
// and in such case ber->ber_len > 0;
if (reTries > 0 && reTries % 5 == 0)
{
VMDIR_LOG_WARNING( VMDIR_LOG_MASK_ALL, "%s: ber_get_next() failed with errno = %d, peer (%s), re-trying (%d)",
__func__, errno , pConn->szClientIP, reTries);
}
VmDirSleep(200);
reTries++;
continue;
}
// Unexpected error case.
if (errno == 0)
{
VMDIR_LOG_INFO( LDAP_DEBUG_CONNS, "%s: ber_get_next() peer (%s) disconnected",
__func__, pConn->szClientIP);
} else
{
VMDIR_LOG_ERROR( VMDIR_LOG_MASK_ALL, "%s: ber_get_next() call failed with errno = %d peer (%s)",
__func__, errno, pConn->szClientIP);
}
retVal = LDAP_NOTICE_OF_DISCONNECT;
BAIL_ON_VMDIR_ERROR( retVal );
}
// Read LDAP request messageID (tag, length (not returned since it is implicit/integer), and messageID value)
if ( (tag = ber_get_int( ber, &msgid )) != LDAP_TAG_MSGID )
{
VMDIR_LOG_ERROR( VMDIR_LOG_MASK_ALL, "ProcessAConnection: ber_get_int() call failed." );
retVal = LDAP_NOTICE_OF_DISCONNECT;
BAIL_ON_VMDIR_ERROR( retVal );
}
// Read protocolOp (tag) and length of the LDAP operation message, and leave the pointer at the beginning
// of the LDAP operation message (to be parsed by PerformXYZ methods).
if ( (tag = ber_peek_tag( ber, &len )) == LBER_ERROR )
{
VMDIR_LOG_ERROR( VMDIR_LOG_MASK_ALL, "ProcessAConnection: ber_peek_tag() call failed." );
retVal = LDAP_NOTICE_OF_DISCONNECT;
BAIL_ON_VMDIR_ERROR( retVal );
}
retVal = VmDirNewOperation(ber, msgid, tag, pConn, &pOperation);
if (retVal)
{
VMDIR_LOG_ERROR( VMDIR_LOG_MASK_ALL, "ProcessAConnection: NewOperation() call failed." );
retVal = LDAP_OPERATIONS_ERROR;
}
BAIL_ON_VMDIR_ERROR( retVal );
//
// If this is a multi-stage operation don't overwrite the start time if it's already set.
//
pConn->SuperLogRec.iStartTime = pConn->SuperLogRec.iStartTime ? pConn->SuperLogRec.iStartTime : VmDirGetTimeInMilliSec();
switch (tag)
{
case LDAP_REQ_BIND:
retVal = VmDirPerformBind(pOperation);
if (retVal != LDAP_SASL_BIND_IN_PROGRESS)
{
_VmDirCollectBindSuperLog(pConn, pOperation); // ignore error
}
break;
case LDAP_REQ_ADD:
retVal = VmDirPerformAdd(pOperation);
break;
case LDAP_REQ_SEARCH:
retVal = VmDirPerformSearch(pOperation);
break;
case LDAP_REQ_UNBIND:
retVal = VmDirPerformUnbind(pOperation);
break;
case LDAP_REQ_MODIFY:
retVal = VmDirPerformModify(pOperation);
break;
case LDAP_REQ_DELETE:
retVal = VmDirPerformDelete(pOperation);
break;
case LDAP_REQ_MODDN:
case LDAP_REQ_COMPARE:
case LDAP_REQ_ABANDON:
case LDAP_REQ_EXTENDED:
VMDIR_LOG_INFO( VMDIR_LOG_MASK_ALL, "ProcessAConnection: Operation is not yet implemented.." );
pOperation->ldapResult.errCode = retVal = LDAP_UNWILLING_TO_PERFORM;
// ignore following VmDirAllocateStringA error.
VmDirAllocateStringA( "Operation is not yet implemented.", &pOperation->ldapResult.pszErrMsg);
VmDirSendLdapResult( pOperation );
break;
default:
pOperation->ldapResult.errCode = LDAP_PROTOCOL_ERROR;
retVal = LDAP_NOTICE_OF_DISCONNECT;
break;
}
pConn->SuperLogRec.iEndTime = VmDirGetTimeInMilliSec();
VmDirOPStatisticUpdate(tag, pConn->SuperLogRec.iEndTime - pConn->SuperLogRec.iStartTime);
if (tag != LDAP_REQ_BIND)
{
VmDirLogOperation(gVmdirGlobals.pLogger, tag, pConn, pOperation->ldapResult.errCode);
_VmDirScrubSuperLogContent(tag, &pConn->SuperLogRec);
}
VmDirFreeOperation(pOperation);
pOperation = NULL;
ber_free( ber, 1);
ber = NULL;
if (retVal == LDAP_NOTICE_OF_DISCONNECT) // returned as a result of protocol parsing error.
{
// RFC 4511, section 4.1.1: If the server receives an LDAPMessage from the client in which the LDAPMessage
// SEQUENCE tag cannot be recognized, the messageID cannot be parsed, the tag of the protocolOp is not
// recognized as a request, or the encoding structures or lengths of data fields are found to be incorrect,
// then the server **SHOULD** return the Notice of Disconnection, with the resultCode
// set to protocolError, and **MUST** immediately terminate the LDAP session as described in Section 5.3.
goto cleanup;
}
}
cleanup:
if (retVal == LDAP_NOTICE_OF_DISCONNECT)
{
// Optionally send Notice of Disconnection with rs->err.
}
if (ber != NULL)
{
ber_free( ber, 1 );
}
VmDirDeleteConnection(&pConn);
VMDIR_SAFE_FREE_MEMORY(pConnCtx);
VmDirFreeOperation(pOperation);
if (bDownOpThrCount)
{
VmDirSyncCounterDecrement(gVmdirGlobals.pOperationThrSyncCounter);
}
_VmDirFlowCtrlThrExit();
// TODO: should we return dwError ?
return 0;
error:
goto cleanup;
}
DWORD
VmDirWriteQueueWait(
PVMDIR_WRITE_QUEUE pWriteQueue,
PVMDIR_WRITE_QUEUE_ELEMENT pWriteQueueEle
)
{
DWORD dwError = 0;
uint64_t iStartTime = 0;
uint64_t iElapsedTime = 0;
BOOLEAN bInLock = FALSE;
PVDIR_LINKED_LIST_NODE pNode = NULL;
PVMDIR_WRITE_QUEUE_ELEMENT pWriteQueueHead = NULL;
if (!pWriteQueue || !pWriteQueueEle)
{
BAIL_WITH_VMDIR_ERROR(dwError, VMDIR_ERROR_INVALID_PARAMETER);
}
VMDIR_LOCK_MUTEX(bInLock, gVmDirServerOpsGlobals.pMutex);
iStartTime = VmDirGetTimeInMilliSec();
//default - timeout 60 seconds
while (VmDirGetTimeInMilliSec() - iStartTime <= gVmdirGlobals.dwWriteTimeoutInMilliSec)
{
VmDirLinkedListGetHead(pWriteQueue->pList, &pNode);
pWriteQueueHead = ((PVMDIR_WRITE_QUEUE_ELEMENT)pNode->pElement);
if (pWriteQueueHead->usn == pWriteQueueEle->usn)
{
iElapsedTime = VmDirGetTimeInMilliSec() - iStartTime;
VMDIR_LOG_INFO(LDAP_DEBUG_WRITE_QUEUE, "%s: usn: %"PRId64, __FUNCTION__, pWriteQueueEle->usn);
break;
}
dwError = VmDirConditionTimedWait(
pWriteQueueEle->pCond,
gVmDirServerOpsGlobals.pMutex,
gVmdirGlobals.dwWriteTimeoutInMilliSec);
}
if (dwError != 0) //ETIMEDOUT
{
// After timeout queueHead could have changed
VmDirLinkedListGetHead(pWriteQueue->pList, &pNode);
if (pNode)
{
pWriteQueueHead = ((PVMDIR_WRITE_QUEUE_ELEMENT)pNode->pElement);
VMDIR_LOG_ERROR(
VMDIR_LOG_MASK_ALL,
"%s: error: %d QueueHeadUSN: %"PRId64 "MyUSN: %"PRId64,
__FUNCTION__,
dwError,
pWriteQueueHead->usn,
pWriteQueueEle->usn);
}
BAIL_WITH_VMDIR_ERROR(dwError, VMDIR_ERROR_ML_WRITE_TIMEOUT);
}
else if (iElapsedTime > gVmdirServerGlobals.dwEfficientWriteOpTimeMS)
{
//log - if more time is spent in the write queue
pWriteQueueHead = ((PVMDIR_WRITE_QUEUE_ELEMENT)pNode->pElement);
VMDIR_LOG_INFO(
VMDIR_LOG_MASK_ALL,
"%s: (Inefficient) time:"PRId64"(ms) HeadUSN: %"PRId64 "MyUSN: %"PRId64 "Queue size:%u",
__FUNCTION__,
iElapsedTime,
pWriteQueueHead->usn,
pWriteQueueEle->usn,
VmDirWriteQueueSizeInLock(pWriteQueue));
}
cleanup:
VMDIR_UNLOCK_MUTEX(bInLock, gVmDirServerOpsGlobals.pMutex);
return dwError;
error:
VMDIR_LOG_ERROR(VMDIR_LOG_MASK_ALL, "failed, error (%d)", dwError);
goto cleanup;
}
