Additional messages:

Jul 10 16:00:06 satellite1 qpidd: 2018-07-10 16:00:06 [System] error JournalInactive:katello_event_queue couldn't setup next timer firing: -481765625ns[500ms]
Jul 10 16:00:06 satellite1 qpidd[17643]: 2018-07-10 16:00:06 [System] error JournalInactive:katello_event_queue couldn't setup next timer firing: -481765625ns[500ms]

Additional messages (but may not be connected):

Jul 10 16:27:25 satellite1 server: Exception in thread "Dispatcher-0-Conn-2117" java.lang.IllegalStateException: dispatcher is not started
Jul 10 16:27:25 satellite1 server: at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3251)
Jul 10 16:27:25 satellite1 server: at org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:54)
Jul 10 16:27:25 satellite1 server: at org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3403)
Jul 10 16:27:25 satellite1 server: at java.lang.Thread.run(Thread.java:748)

More messages:

Jul 10 18:02:22 satellite1 puppet-master[8519]: Starting Puppet master version 3.8.6
Jul 10 18:02:22 satellite1 puppet-master[8542]: The environment must be purely alphanumeric, not ''
Jul 11 01:38:21 satellite1 qpidd: 2018-07-11 01:38:21 [System] error JournalInactive:celery couldn't setup next timer firing: -497884899ns[500ms]
Jul 11 01:38:21 satellite1 qpidd[17643]: 2018-07-11 01:38:21 [System] error JournalInactive:celery couldn't setup next timer firing: -497884899ns[500ms]
Jul 11 03:43:02 satellite1 su: (to foreman) root on none
Jul 11 10:50:19 satellite1 qpidd[17643]: 2018-07-11 10:50:19 [System] error JournalInactive:celery couldn't setup next timer firing: -447291083ns[500ms]
Jul 11 10:50:19 satellite1 qpidd: 2018-07-11 10:50:19 [System] error JournalInactive:celery couldn't setup next timer firing: -447291083ns[500ms]
Jul 11 11:27:26 satellite1 qpidd[17643]: 2018-07-11 11:27:26 [System] error JournalInactive:reserved_resource_worker-3.uis.private.cam.ac.uk.dq couldn't setup next timer firing: -489401776ns[500ms]
Jul 11 11:27:26 satellite1 qpidd: 2018-07-11 11:27:26 [System] error JournalInactive:reserved_resource_worker-3.uis.private.cam.ac.uk.dq couldn't setup next timer firing: -489401776ns[500ms]
Jul 11 11:40:19 satellite1 qpidd: 2018-07-11 11:40:19 [System] error JournalInactive:celery couldn't setup next timer firing: -490328521ns[500ms]
Jul 11 11:40:19 satellite1 qpidd[17643]: 2018-07-11 11:40:19 [System] error JournalInactive:celery couldn't setup next timer firing: -490328521ns[500ms]

Hello,
I recommend raising support case rather than filing bugzilla. The above might not be a bug but e.g. configuration issue (i.e. system time updated at some unfortunate time, causing qpidd internal timers get confused?). To investigate that, please open a support case via

https://access.redhat.com

and attach sosreport for start.

(won't katello-service restart remedy the problem? that would be also worth to try / know)

I did a katello-service restart at 15:03 or so and saw similar errors at 16:07.  I've opened a support call on your recommendation.

https://access.redhat.com/support/cases/#/case/02139101, if you can see it.

Kim,
do you have an idea of reproducer for the above error log? And could you confrm the error log is harm-less?

customer is on qpid-cpp-server-linearstore 1.36-18, so up-to-date *except for* the deadlock BZ https://bugzilla.redhat.com/show_bug.cgi?id=1588015#c8


My source code analysis when 
JournalInactive:..... couldn't setup next timer firing: -338090542ns[500ms]
can happen:

1) in https://github.com/apache/qpid-cpp/blob/master/src/qpid/sys/Timer.cpp#L82 :
- when the timer wants to setup next fire, nextFireTime > AbsTime::now(), meaning there is no reason to set up yet
- the negative values is a bug, there should be reverse comparison; then the numbers make sense (values up to 500ms what is default of journal-flush-timeout)

2) in https://github.com/apache/qpid-cpp/blob/master/src/qpid/linearstore/JournalImpl.cpp#L46 :
- setupNextFire was called _before_ the timer was really fired (that caused the 1) )
- more technically from Timer.cpp, setupNextFire or restart method was called before it should / concurrently (as sometimes the value delay is almost 500ms what the period is)
- that means, InactivityFireEvent::reset was called twice within the 500ms period without firing the timer meantime; both times in state either FIRED or FLUSHED
- the method body is under a lock, so state was changed from FIRED/FLUSHED to RUNNING, then somehow to FLUSHED before 2nd call of reset method
- so InactivityFireEvent::flush must be called a short time after InactivityFireEvent::fire, before timer was executed
- that is invoked from JournalImpl::flush only
- that is invoked from:
  - MessageStoreImpl::flush
  - TxnCtxt::jrnl_flush (transactions not used, not relevant)
  - jcntl::flush (??)

That brought me to the reproducer attempt in frequent sending sole messages like:

while true; do
		qpid-send -a DurableQueue -m 1 --content-size=1390 -durable=true --capacity=1
done

but without getting that error.


(I solely see that error on some our Satellites, but without an evident trigger)

Adding some debugs, here is a sequence of calls of InactivityFireEvent methods that lead to the error log ("starts" means method is called, "executed" means method acquired the _ifeStateLock lock):


- flush starts with _state=RUNNING
- fire starts with _state=RUNNING
- flush is executed, setting _state=FLUSHED
- reset starts with _state=FLUSHED
- reset is executed, setting _state=RUNNING (and nextFireTime="now+500ms")
- fire is executed, setting _state=FIRED
- 2nd reset starts with _state=FIRED
- 2nd reset is attempted to be executed - too soon after 1st reset, so it fails in setupNextFire

(In reply to Pavel Moravec from comment #7)
> Adding some debugs, here is a sequence of calls of InactivityFireEvent
> methods that lead to the error log ("starts" means method is called,
> "executed" means method acquired the _ifeStateLock lock):
> 
> 
> - flush starts with _state=RUNNING
> - fire starts with _state=RUNNING
> - flush is executed, setting _state=FLUSHED
> - reset starts with _state=FLUSHED
> - reset is executed, setting _state=RUNNING (and nextFireTime="now+500ms")
> - fire is executed, setting _state=FIRED
> - 2nd reset starts with _state=FIRED
> - 2nd reset is attempted to be executed - too soon after 1st reset, so it
> fails in setupNextFire

That means, the problem is when:

- Timer fires fire() method
- before the method is executed, inactivity fire event performs flush and reset
- fire is completed
- another reset comes too soon

OK, here is a VERY reliable reproducer, generating the error log within seconds:

# run qpidd with small jrnl flush timeout, to really really speed the reproducer
qpidd --journal-flush-timeout=50ms &

# receive messages from durable queue - just to prevent queue full
queue="DurableQueue; {create: always, node:{ type:queue, durable:true}}"
qpid-receive -a "$queue" --print-content=no -f &

# in a loop, send messages concurrently, triggering flush by each producer
while true; do 
  for i in $(seq 1 30); do
    qpid-send -a "$queue" --content-size=123456 --durable=true -m1 &
  done
  while [ $(pgrep qpid-send | wc -l) -gt 0 ]; do
    sleep 1
  done
done

FYI the error log does not appear in 1.36.0-9. So I assume it popped up due to QPID-7975 or QPID-7895.

I am starting to take a look at this, I will provide some feedback shortly when I have had a chance to pick at it for a little while...

I agree with Pavel's analysis. This error occurs when the following conditions are met:

1. The timer is in state RUNNING.

2. flush(), reset() and fire() events occur on separate threads almost simultaneously. The flush() event acquires _ifeStateLock first, followed by reset(), then fire().

3. A second reset() occurs within the time set on the timer in condition 2.

This will cause the following sequence:

a. flush() flushes the store, putting the timer into state FLUSHED.
b. flush() releases _ifeStateLock, allowing reset() to acquire the lock.
c. reset() calls Timer::restart(), adding Timer::period to Timer::nextFireTime. The timer is set into state RUNNING. reset() releases the lock, allowing fire() to acquire it.
d. fire() flushes the store again (inefficient, but benign), then timer is put into state FIRED. This is technically an errored state, as Timer::nextFireTime is no longer ready to fire.

If at any time while Timer::nextFireTime is still not yet ready to fire (ie within the period set in step c above):

e. reset() is called, and as the timer is in state FIRED, allows Timer::setupNextFire() to be called.  This results in the "couldn't setup next timer firing" error message described in this bugzilla.

From this analysis, I can see:
1. This is a race condition;
2. It was introduced when this state machine was added to JournalImpl::InactivityFireEvent to solve another issue;
3. This sequence of events does not affect the operation of the timer in any way, and is benign (other than the confusing error messages that show up in the broker log file).

I will look at a way to solve this, and I don't think it is serious from an operational point-of-view.

By changing the way the timer is set up for the next firing, this error message can be avoided. This is done by calling restart() instead of setUpNextFiring(). Initial testing has shown that there is no discernible difference in timer or journal behavior, other than the error message is no longer present. This solution also avoids any risky changes to the timer state machine.

Proposed fix committed:

Commit 428eafa1f65e22e04ea63b73aebcc192282df72c in qpid-cpp's branch refs/heads/master from Kim van der Riet
[ https://git-wip-us.apache.org/repos/asf?p=qpid-cpp.git;h=428eafa ]

QPID-8220: Proposed fix for timer error message issue, also minor change to error message itself to make less confusing

Can you confirm the following messages are associated, please?

Aug 17 14:09:57 satellite1 server: Exception in thread "Dispatcher-0-Conn-1130" java.lang.IllegalStateException: dispatcher is not started
Aug 17 14:09:57 satellite1 server: at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3251)
Aug 17 14:09:57 satellite1 server: at org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:54)
Aug 17 14:09:57 satellite1 server: at org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3403)
Aug 17 14:09:57 satellite1 server: at java.lang.Thread.run(Thread.java:748)

(In reply to Ben from comment #17)
> Can you confirm the following messages are associated, please?
> 
> Aug 17 14:09:57 satellite1 server: Exception in thread
> "Dispatcher-0-Conn-1130" java.lang.IllegalStateException: dispatcher is not
> started
> Aug 17 14:09:57 satellite1 server: at
> org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3251)
> Aug 17 14:09:57 satellite1 server: at
> org.apache.qpid.client.message.UnprocessedMessage.
> dispatch(UnprocessedMessage.java:54)
> Aug 17 14:09:57 satellite1 server: at
> org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3403)
> Aug 17 14:09:57 satellite1 server: at java.lang.Thread.run(Thread.java:748)

It shouldnt be. Assuming this is from /var/log/messages on Satellite6 server, this is a message from a java client, that must be candlepin (or some non-Satellite client?). First it is werid that candlepin is logging to /var/log/messages at all, second the journal errors dont have any impact to broker or its behavour.

Yup, this is in /var/log/messages.  And I assume it's Candlepin as there's nothing else on the box it could be.  I guess this is another issue, then?  Oh dear.

(In reply to Ben from comment #19)
> Yup, this is in /var/log/messages.  And I assume it's Candlepin as there's
> nothing else on the box it could be.  I guess this is another issue, then? 
> Oh dear.

It seems like a separate issue - please file new support case and attach a new sosreport there (an older one with such error shall be sufficient, but might not be in 100% cases).

Thank you for your interest in Satellite 6. We have evaluated this request, and while we recognize that it is a valid request, we do not expect this to be implemented in the product in the foreseeable future. This is due to other priorities for the product, and not a reflection on the request itself. We are therefore closing this out as WONTFIX. If you have any concerns about this, please do not reopen. Instead, feel free to contact Red Hat Technical Support.

Closed.