/* This callback is called when client transaction state has changed */
static void tsx_completion_cb(void *token, pjsip_event *event)
{
pjsip_transaction *tsx;
PJ_UNUSED_ARG(token);
if (event->type != PJSIP_EVENT_TSX_STATE)
return;
tsx = event->body.tsx_state.tsx;
if (tsx->mod_data[mod_test.id] != NULL) {
/* This transaction has been calculated before */
return;
}
if (tsx->state==PJSIP_TSX_STATE_TERMINATED) {
report_completion(tsx->status_code);
tsx->mod_data[mod_test.id] = (void*)1;
}
else if (tsx->method.id == PJSIP_INVITE_METHOD &&
tsx->state == PJSIP_TSX_STATE_CONFIRMED) {
report_completion(tsx->status_code);
tsx->mod_data[mod_test.id] = (void*)1;
} else if (tsx->state == PJSIP_TSX_STATE_COMPLETED) {
report_completion(tsx->status_code);
tsx->mod_data[mod_test.id] = (void*)1;
TERMINATE_TSX(tsx, tsx->status_code);
}
}
/* Send one stateless request */
static pj_status_t submit_stateless_job(void)
{
pjsip_tx_data *tdata;
pj_status_t status;
status = pjsip_endpt_create_request(app.sip_endpt, &app.client.method,
&app.client.dst_uri, &app.local_uri,
&app.client.dst_uri, &app.local_contact,
NULL, -1, NULL, &tdata);
if (status != PJ_SUCCESS) {
app_perror(THIS_FILE, "Error creating request", status);
report_completion(701);
return status;
}
status = pjsip_endpt_send_request_stateless(app.sip_endpt, tdata, NULL,
NULL);
if (status != PJ_SUCCESS) {
pjsip_tx_data_dec_ref(tdata);
app_perror(THIS_FILE, "Error sending stateless request", status);
report_completion(701);
return status;
}
return PJ_SUCCESS;
}
/* This is notification from the call when the call state has changed.
* This is called for client calls only.
*/
static void call_on_state_changed( pjsip_inv_session *inv,
pjsip_event *e)
{
PJ_UNUSED_ARG(e);
/* Bail out if the session has been counted before */
if (inv->mod_data[mod_test.id] != NULL)
return;
/* Bail out if this is not an outgoing call */
if (inv->role != PJSIP_UAC_ROLE)
return;
if (inv->state == PJSIP_INV_STATE_CONFIRMED) {
pjsip_tx_data *tdata;
pj_status_t status;
//report_completion(200);
//inv->mod_data[mod_test.id] = (void*)1;
status = pjsip_inv_end_session(inv, PJSIP_SC_OK, NULL, &tdata);
if (status == PJ_SUCCESS && tdata)
status = pjsip_inv_send_msg(inv, tdata);
} else if (inv->state == PJSIP_INV_STATE_DISCONNECTED) {
report_completion(inv->cause);
inv->mod_data[mod_test.id] = (void*)1;
}
}
/* Send one stateful request */
static pj_status_t submit_job(void)
{
pjsip_tx_data *tdata;
pj_status_t status;
status = pjsip_endpt_create_request(app.sip_endpt, &app.client.method,
&app.client.dst_uri, &app.local_uri,
&app.client.dst_uri, &app.local_contact,
NULL, -1, NULL, &tdata);
if (status != PJ_SUCCESS) {
app_perror(THIS_FILE, "Error creating request", status);
report_completion(701);
return status;
}
status = pjsip_endpt_send_request(app.sip_endpt, tdata, -1, NULL,
&tsx_completion_cb);
if (status != PJ_SUCCESS) {
app_perror(THIS_FILE, "Error sending stateful request", status);
//should have been reported by tsx_completion_cb().
//report_completion(701);
//No longer necessary (r777)
//pjsip_tx_data_dec_ref(tdata);
}
return status;
}
/* Handler when response is received. */
static pj_bool_t mod_test_on_rx_response(pjsip_rx_data *rdata)
{
if (pjsip_rdata_get_tsx(rdata) == NULL) {
report_completion(rdata->msg_info.msg->line.status.code);
}
return PJ_TRUE;
}
void cmd::proxy_binding_retry(const boost::system::error_code& ec, proxy_binding_info& pbinfo)
{
if (ec) {
if (ec != boost::system::errc::make_error_condition(boost::system::errc::operation_canceled))
_log(0, "PBU retry timer error: ", ec.message());
return;
}
bulist_entry* be = _bulist.find(pbinfo.id);
if (!be || (be->bind_status != bulist_entry::k_bind_requested
&& be->bind_status != bulist_entry::k_bind_renewing
&& be->bind_status != bulist_entry::k_bind_detach)) {
_log(0, "PBU retry error: binding update list entry not found [id = ", pbinfo.id, ", cmd = ", pbinfo.address, "]");
return;
}
++be->retry_count;
if (be->bind_status == bulist_entry::k_bind_detach && be->retry_count > 3) {
report_completion(_service, be->completion, boost::system::error_code(ec_timeout, mag_error_category()));
_log(0, "PBU retry error: max retry count [id = ", pbinfo.id, ", cmd = ", pbinfo.address, "]");
_bulist.remove(be);
return;
}
pbu_sender_ptr pbus(new pbu_sender(pbinfo));
double delay = std::min<double>(32, std::pow(1.5f, be->retry_count)); //FIXME: validate
pbus->async_send(_mp_sock, boost::bind(&mag::mp_send_handler, this, _1));
be->timer.expires_from_now(boost::posix_time::milliseconds(delay * 1000.f));
be->timer.async_wait(_service.wrap(boost::bind(&mag::proxy_binding_retry, this, _1, pbinfo)));
if (pbinfo.lifetime)
_log(0, "PBU register retry [id = ", pbinfo.id,
", cmd = ", pbinfo.address,
", sequence = ", pbinfo.sequence,
", retry_count = ", uint(be->retry_count),
", delay = ", delay, "]");
else
_log(0, "PBU de-register retry [id = ", pbinfo.id,
", cmd = ", pbinfo.address,
", sequence = ", pbinfo.sequence,
", retry_count = ", uint(be->retry_count),
", delay = ", delay, "]");
}
ErrorStack LogMapper::handle_process() {
const Epoch base_epoch = parent_.get_base_epoch();
const Epoch until_epoch = parent_.get_valid_until_epoch();
log::LoggerRef logger = engine_->get_log_manager()->get_logger(id_);
const log::LogRange log_range = logger.get_log_range(base_epoch, until_epoch);
// uint64_t cur_offset = log_range.begin_offset;
if (log_range.is_empty()) {
LOG(INFO) << to_string() << " has no logs to process";
report_completion(0);
return kRetOk;
}
// open the file and seek to there. be careful on page boundary.
// as we use direct I/O, all I/O must be 4kb-aligned. when the read range is not
// a multiply of 4kb, we read a little bit more (at most 4kb per read, so negligible).
// to clarify, here we use the following suffixes
// "infile"/"inbuf" : the offset is an offset in entire file/IO buffer
// "aligned" : the offset is 4kb-aligned (careful on floor vs ceil)
// Lengthy, but otherwise it's so confusing.
processed_log_count_ = 0;
IoBufStatus status;
status.size_inbuf_aligned_ = io_buffer_.get_size();
status.cur_file_ordinal_ = log_range.begin_file_ordinal;
status.ended_ = false;
status.first_read_ = true;
debugging::StopWatch watch;
while (!status.ended_) { // loop for log file switch
fs::Path path(engine_->get_options().log_.construct_suffixed_log_path(
numa_node_,
id_,
status.cur_file_ordinal_));
uint64_t file_size = fs::file_size(path);
if (file_size % kIoAlignment != 0) {
LOG(WARNING) << to_string() << " Interesting, non-aligned file size, which probably means"
<< " previous writes didn't flush. file path=" << path << ", file size=" << file_size;
file_size = align_io_floor(file_size);
}
ASSERT_ND(file_size % kIoAlignment == 0);
status.size_infile_aligned_ = file_size;
// If this is the first file to read, we might be reading from non-zero position.
// In that case, be careful on alignment.
if (status.cur_file_ordinal_ == log_range.begin_file_ordinal) {
status.next_infile_ = log_range.begin_offset;
} else {
status.next_infile_ = 0;
}
if (status.cur_file_ordinal_ == log_range.end_file_ordinal) {
ASSERT_ND(log_range.end_offset <= file_size);
status.end_infile_ = log_range.end_offset;
} else {
status.end_infile_ = file_size;
}
DVLOG(1) << to_string() << " file path=" << path << ", file size=" << assorted::Hex(file_size)
<< ", read_end=" << assorted::Hex(status.end_infile_);
fs::DirectIoFile file(path, engine_->get_options().snapshot_.emulation_);
WRAP_ERROR_CODE(file.open(true, false, false, false));
DVLOG(1) << to_string() << "opened log file " << file;
while (true) {
WRAP_ERROR_CODE(check_cancelled()); // check per each read
status.buf_infile_aligned_ = align_io_floor(status.next_infile_);
WRAP_ERROR_CODE(file.seek(status.buf_infile_aligned_, fs::DirectIoFile::kDirectIoSeekSet));
DVLOG(1) << to_string() << " seeked to: " << assorted::Hex(status.buf_infile_aligned_);
status.end_inbuf_aligned_ = std::min(
io_buffer_.get_size(),
align_io_ceil(status.end_infile_ - status.buf_infile_aligned_));
ASSERT_ND(status.end_inbuf_aligned_ % kIoAlignment == 0);
WRAP_ERROR_CODE(file.read(status.end_inbuf_aligned_, &io_buffer_));
status.cur_inbuf_ = 0;
if (status.next_infile_ != status.buf_infile_aligned_) {
ASSERT_ND(status.next_infile_ > status.buf_infile_aligned_);
status.cur_inbuf_ = status.next_infile_ - status.buf_infile_aligned_;
status.cur_inbuf_ = status.next_infile_ - status.buf_infile_aligned_;
DVLOG(1) << to_string() << " skipped " << status.cur_inbuf_ << " bytes for aligned read";
}
CHECK_ERROR(handle_process_buffer(file, &status));
if (status.more_in_the_file_) {
ASSERT_ND(status.next_infile_ > status.buf_infile_aligned_);
} else {
if (log_range.end_file_ordinal == status.cur_file_ordinal_) {
status.ended_ = true;
break;
} else {
++status.cur_file_ordinal_;
status.next_infile_ = 0;
LOG(INFO) << to_string()
<< " moved on to next log file ordinal " << status.cur_file_ordinal_;
}
}
}
file.close();
}
watch.stop();
LOG(INFO) << to_string() << " processed " << processed_log_count_ << " log entries in "
<< watch.elapsed_sec() << "s";
report_completion(watch.elapsed_sec());
return kRetOk;
}
void cmd::proxy_binding_ack(const proxy_binding_info& pbinfo, chrono& delay)
{
bulist_entry* be = _bulist.find(pbinfo.id);
if (!be) {
_log(0, "PBA error: binding update list entry not found [id = ", pbinfo.id, ", cmd = ", pbinfo.address, "]");
return;
}
if (be->cmd_address() != pbinfo.address) {
_log(0, "PBA error: not this CMD [id = ", pbinfo.id, ", cmd = ", pbinfo.address, "]");
return;
}
if (pbinfo.status == ip::mproto::pba::status_bad_sequence) {
_log(0, "PBA error: bad sequence number [id = ", pbinfo.id,
", cmd = ", pbinfo.address,
", sequence = ", be->sequence_number,
", last accepted sequence = ", pbinfo.sequence, "]");
be->sequence_number = pbinfo.sequence;
proxy_binding_info pbinfo;
pbinfo.id = be->mn_id();
pbinfo.address = be->cmd_address();
pbinfo.handoff = ip::mproto::option::handoff::k_unknown;
pbinfo.sequence = ++be->sequence_number;
pbinfo.lifetime = (be->bind_status != bulist_entry::k_bind_detach) ? be->lifetime : 0;
pbinfo.prefix_list = be->mn_prefix_list();
pbu_sender_ptr pbus(new pbu_sender(pbinfo));
pbus->async_send(_mp_sock, boost::bind(&mag::mp_send_handler, this, _1));
be->timer.cancel();
be->timer.expires_from_now(boost::posix_time::milliseconds(1500));
be->timer.async_wait(_service.wrap(boost::bind(&mag::proxy_binding_retry, this, _1, pbinfo)));
return;
}
if (pbinfo.sequence != be->sequence_number) {
_log(0, "PBA error: sequence number invalid [id = ", pbinfo.id,
", cmd = ", pbinfo.address,
", sequence = ", pbinfo.sequence,
" != ", be->sequence_number, "]");
return;
}
if (pbinfo.lifetime && (be->bind_status == bulist_entry::k_bind_requested
|| be->bind_status == bulist_entry::k_bind_renewing)) {
boost::system::error_code ec;
if (pbinfo.status == ip::mproto::pba::status_ok) {
if (be->bind_status == bulist_entry::k_bind_requested)
add_route_entries(*be);
} else {
ec = boost::system::error_code(pbinfo.status, pba_error_category());
}
be->timer.cancel();
be->handover_delay.stop();
if (be->bind_status == bulist_entry::k_bind_requested) {
report_completion(_service, be->completion, ec);
_log(0, "PBA registration [delay = ", be->handover_delay.get(),
", id = ", pbinfo.id,
", cmd = ", pbinfo.address,
", status = ", pbinfo.status, "]");
} else {
_log(0, "PBA re-registration [delay = ", be->handover_delay.get(),
", id = ", pbinfo.id,
", cmd = ", pbinfo.address,
", status = ", pbinfo.status, "]");
}
be->bind_status = bulist_entry::k_bind_ack;
if (pbinfo.status == ip::mproto::pba::status_ok) {
//Will try to renew 3 seconds before binding expires or 1 second if lifetime <= 6
uint expire = (pbinfo.lifetime <= 6) ? pbinfo.lifetime - 1 : pbinfo.lifetime - 3; //FIXME Check used values
be->timer.expires_from_now(boost::posix_time::seconds(expire));
be->timer.async_wait(_service.wrap(boost::bind(&mag::proxy_binding_renew, this, _1, pbinfo.id)));
} else {
_bulist.remove(be);
}
delay.stop();
_log(0, "PBA register process delay ", delay.get());
} else if (!pbinfo.lifetime && be->bind_status == bulist_entry::k_bind_detach) {
boost::system::error_code ec;
if (pbinfo.status == ip::mproto::pba::status_ok)
ec = boost::system::error_code(pbinfo.status, pba_error_category());
be->timer.cancel();
be->handover_delay.stop();
report_completion(_service, be->completion, ec);
_log(0, "PBA de-registration [delay = ", be->handover_delay.get(),
", id = ", pbinfo.id,
", cmd = ", pbinfo.address, "]");
_bulist.remove(be);
delay.stop();
_log(0, "PBA de-register process delay ", delay.get());
} else {
_log(0, "PBA ignored [id = ", pbinfo.id, ", cmd = ", pbinfo.address, ", status = ", be->bind_status, "]");
}
}
