Last updated on NOVEMBER 04, 2016

Applies to:

Symptoms

When a device operation is performed, an error appears in the JMService log and in the TCDBService log:

JMService log --

03/20 15:43:52: JMService 0xc,ctp=60000000000ebd58,"JMBroadcast::flush(writeToDB) - writing" *ERROR* - sql failed:
  result=-1 error=''
  sql=[insert into job_steps(id, step_idx, event_idx, event_app, assoc_id, external_id, curr_event_idx) values(job_steps_seq.nextval, 
:step_idx, :event_idx, :app, :assoc, :eid, :curr_eidx)]
  host_vars=[{
  step_idx:{3469748 3469747 }
  event_idx:{2452793 2452793 }
  app:{0 0 }
  assoc:{0 4 }
  eid:{'QE10050727' 'QE10050727' }
  curr_eidx:{2452793 2452793 }
}]
03/20 15:43:52: JMService 0xc,ctp=60000000000ebd58,"JMBroadcast::flush(writeToDB) - writing" JMStepWriter::write - sql returned -1
  sql=[insert into job_steps(id, step_idx, event_idx, event_app, assoc_id, external_id, curr_event_idx) values(job_steps_seq.nextval, 
:step_idx, :event_idx, :app, :assoc, :eid, :curr_eidx)]
  host_vars=[{
  step_idx:{3469748 3469747 }
  event_idx:{2452793 2452793 }
  app:{0 0 }
  assoc:{0 4 }
  eid:{'QE10050727' 'QE10050727' }
  curr_eidx:{2452793 2452793 }
}]

TCDBService log (with debug enabled) --

03/20 15:43:52: dbrdwr:3247 
-- ORACLE ERROR -- OCI return code from OCIStmtExecute is OCI_NO_DATA
while processing command 'insert into job_steps(id, step_idx, event_idx, event_app, assoc_id, external_id, curr_event_idx)
 values(job_steps_seq.nextval, :step_idx, :event_idx, :app, :assoc, :eid, :curr_eidx)'parse offset = 12[job_steps(id, step_] 
03/20 15:43:52: dbrdwr:3247 *ERROR* - sql failed:
  result=-1 error=''
  sql=[insert into job_steps(id, step_idx, event_idx, event_app, assoc_id, external_id, curr_event_idx) values(job_steps_seq.nextval, 
:step_idx, :event_idx, :app, :assoc, :eid, :curr_eidx)]
  host_vars=[{
  step_idx:{3469748 3469747 }
  event_idx:{2452793 2452793 }
  app:{0 0 }
  assoc:{0 4 }
  eid:{'QE10050727' 'QE10050727' }
  curr_eidx:{2452793 2452793 }
}]
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBOutboard::do_sql got back -1, ''
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" *ERROR* - sql failed:
  result=-1 error=''
  sql=[insert into job_steps(id, step_idx, event_idx, event_app, assoc_id, external_id, curr_event_idx) values(job_steps_seq.nextval, 
:step_idx, :event_idx, :app, :assoc, :eid, :curr_eidx)]
  host_vars=[{
  step_idx:{3469748 3469747 }
  event_idx:{2452793 2452793 }
  app:{0 0 }
  assoc:{0 4 }
  eid:{'QE10050727' 'QE10050727' }
  curr_eidx:{2452793 2452793 }
}]
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" Skipping msg_rendezvous because there are only 1 participants
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBService::sql replying
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBService::sql replying -1, 0
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBService::sql reply sent
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBService::sql reply sent
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" sql error: (insert into job_steps(id, step_idx, event_idx, event_app, assoc_id, external_id,
 curr_event_idx) values(job_steps_seq.nextval, :step_idx, :event_idx, :app, :assoc, :eid, :curr_eidx)) from (1/60:23828.0), result=-1 
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" releasing DBConnection 9fffffff5fdf0570
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" This transaction still has time to live
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBConnection::Rep::decr refcount = 0
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBConnection(9fffffff5fdf0570 setting rep to 0
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" returning from sql
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBConnection::~DBConnection 9fffffff5fdf0570
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" releasing DBConnection 9fffffff5fdf0570
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" DBConnection(9fffffff5fdf0570 setting rep to 0
03/20 15:43:52: 0x8,ctp=60000000000aeb48,"sql" THREAD-TIMING: routine=sql cputime=0.000000 walltime=0.021174
03/20 15:43:52: 0x9,ctp=60000000003b5858,"sql::dispatch" sql request abort_transaction
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" looking for a DBConnection for Xid (1/60:23828.0):2
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" Got it
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" databases::get() returned 6000000000013050
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" DBConnection successful (1 active) rep = 6000000000013050
03/20 15:43:52: 0xa,ctp=6000000000094c38,"pls_forward" THREAD-TIMING: routine=pls_forward cputime=0.000000 walltime=0.000228
03/20 15:43:52: 0x8,ctp=60000000000dbd48,"pls_forward" THREAD-TIMING: routine=pls_forward cputime=0.000000 walltime=0.000381
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" DBOutboard::abortTransaction got back 0, ''
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" Removing from session list
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" DBConnection::~DBConnection 9fffffff5fd80980
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" releasing DBConnection 9fffffff5fd80980
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" DBConnection(9fffffff5fd80980)::release rep 6000000000013050
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" DBConnection::Rep::decr putting 6000000000013050 back on queue
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" DBConnection::Rep::decr refcount = 0
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" DBConnection(9fffffff5fd80980 setting rep to 0
03/20 15:43:52: 0x9,ctp=60000000003b5858,"abort_transaction" THREAD-TIMING: routine=abort_transaction cputime=0.000000 walltime=0.001359

Cause