0013774: since 2018.02.1, the regular maintenance cronjobs dont die and accumulate until there is no more free memory left #6812

Open
Gloirin opened this Issue Jun 9, 2018 · 8 comments

Comments

Projects
None yet
2 participants
@Gloirin

Gloirin commented Jun 9, 2018

Reported by bammes on 22 Feb 2018 20:16

Version: 2018.02.1 Community Edition

The regular maintenance Cronjobs get stuck with the following queries hanging until the database-connection times out:

Crontab:
*/5 * * * * www /usr/local/bin/php -d include_path=.:/usr/local/www/calendar.example.com:/usr/local/www/calendar.example.com/library /usr/local/www/calendar.example.com/tine20.php --method Tinebase.triggerAsyncEvents

Queries:
4879 calendar www-1 calendar 2 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
5532 calendar www-1 calendar 2 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
5190 calendar www-1 calendar 3 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
5679 calendar www-1 calendar 3 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
5797 calendar www-1 calendar 3 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
3440 calendar www-1 calendar 4 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
3911 calendar www-1 calendar 4 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
4383 calendar www-1 calendar 4 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
5039 calendar www-1 calendar 4 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')
5375 calendar www-1 calendar 4 Query UPDATE tine20_container SET content_seq = (CASE WHEN content_seq >= 1 THEN content_seq + 1 ELSE 1 END) WHERE (id = '46')

log is full of these entries:

f0388 cronuser - 2018-02-22T20:05:00+00:00 WARN (4): Tinebase_Backend_Scheduler::cleanZombieTasks::121 cleaning up zombie scheduler task: Array
(
[id] => dd790704ab9e121b7038001785b94959d00d7687
[name] => Calendar_Controller_Event::updateConstraintsExdates
[config] => {"cron":"0 0 * * *","callables":[{"controller":"Calendar_Controller_Event","method":"updateConstraintsExdates"}]}
[last_run] => 2018-02-21 00:15:02
[last_duration] => 1337
[lock_id] => Tinebase_Backend_Scheduler::markTaskRunning::1b6b343531048164cee8e75b1c1bda8c61a0272b
[next_run] => 2018-02-22 00:00:00
[last_failure] =>
[failure_count] => 0
[server_time] => 2018-02-22 20:05:00
)

@Gloirin Gloirin self-assigned this Jun 9, 2018

@Gloirin

This comment has been minimized.

Show comment
Hide comment
@Gloirin

Gloirin Jun 11, 2018

Comment posted by bammes on 27 Feb 2018 15:23

Looks like this is some deadlock when multiple cronjobs run at the same time.
I just solved this for me, using this simple bash-wrapper:

Please note, that from time to time, it takes an excessive amount of time for the cronjob to finish (up to 10 hours). This looks like something is broken.

#!/usr/local/bin/bash
LOCKFILE="/tmp/tine20async.lock"
LOGGER="/usr/bin/logger -t tine20async"
if [ ! -e $LOCKFILE ]; then
date > $LOCKFILE
echo "starting triggerAsyncEvents" | $LOGGER
command="/usr/local/bin/php -d include_path=.:/usr/local/www/calendar.postadigitale.de:/usr/local/www/calendar.postadigitale.de/library /usr/local/www/calendar.postadigitale.de/tine20.php --method Tinebase.triggerAsyncEvents"
echo $command | $LOGGER
{ time $command ; } 2>&1 | $LOGGER
echo "finished triggerAsyncEvents" | $LOGGER
rm $LOCKFILE
else
echo "another instance still running" | $LOGGER
fi

Gloirin commented Jun 11, 2018

Comment posted by bammes on 27 Feb 2018 15:23

Looks like this is some deadlock when multiple cronjobs run at the same time.
I just solved this for me, using this simple bash-wrapper:

Please note, that from time to time, it takes an excessive amount of time for the cronjob to finish (up to 10 hours). This looks like something is broken.

#!/usr/local/bin/bash
LOCKFILE="/tmp/tine20async.lock"
LOGGER="/usr/bin/logger -t tine20async"
if [ ! -e $LOCKFILE ]; then
date > $LOCKFILE
echo "starting triggerAsyncEvents" | $LOGGER
command="/usr/local/bin/php -d include_path=.:/usr/local/www/calendar.postadigitale.de:/usr/local/www/calendar.postadigitale.de/library /usr/local/www/calendar.postadigitale.de/tine20.php --method Tinebase.triggerAsyncEvents"
echo $command | $LOGGER
{ time $command ; } 2>&1 | $LOGGER
echo "finished triggerAsyncEvents" | $LOGGER
rm $LOCKFILE
else
echo "another instance still running" | $LOGGER
fi

@Gloirin

This comment has been minimized.

Show comment
Hide comment
@Gloirin

Gloirin Jun 11, 2018

Comment posted by pmehrer on 13 Mar 2018 20:26

there are two problems here: one with the scheduler (the call to Tinebase.triggerAsyncEvents) and you worked around it.

the second problem is that Calendar_Controller_Event::updateConstraintsExdates seems to get stuck. Lets work on that first: Can you provide logs from one of theose 10 hours runs? like
grep 'cronuser' ....../logfile

Gloirin commented Jun 11, 2018

Comment posted by pmehrer on 13 Mar 2018 20:26

there are two problems here: one with the scheduler (the call to Tinebase.triggerAsyncEvents) and you worked around it.

the second problem is that Calendar_Controller_Event::updateConstraintsExdates seems to get stuck. Lets work on that first: Can you provide logs from one of theose 10 hours runs? like
grep 'cronuser' ....../logfile

@Gloirin

This comment has been minimized.

Show comment
Hide comment
@Gloirin

Gloirin Jun 11, 2018

Comment posted by bammes on 14 Mar 2018 11:22

I am sorry, with the implementation of this semaphore-like mechanism, the problem disappeared after about half a week and unfortunately logrotate did its job...
If I ever see this problem again, I will let you know!

Gloirin commented Jun 11, 2018

Comment posted by bammes on 14 Mar 2018 11:22

I am sorry, with the implementation of this semaphore-like mechanism, the problem disappeared after about half a week and unfortunately logrotate did its job...
If I ever see this problem again, I will let you know!

@Gloirin

This comment has been minimized.

Show comment
Hide comment
@Gloirin

Gloirin Jun 11, 2018

Comment posted by bammes on 14 Mar 2018 11:28

Short analysis of what I have in my general syslog right now shows only one occurence today with 629 minutes.
I will raise the loglevel again and keep you posted.

root@www-1:~ # bzgrep tine20async /var/log/messages | grep real
Mar 13 13:05:00 www-1 tine20async: real 0m0.664s
Mar 13 13:10:00 www-1 tine20async: real 0m0.730s
Mar 13 13:15:00 www-1 tine20async: real 0m0.683s
Mar 13 13:20:01 www-1 tine20async: real 0m1.668s
Mar 13 13:25:01 www-1 tine20async: real 0m1.080s
Mar 13 13:30:01 www-1 tine20async: real 0m1.955s
Mar 13 13:35:00 www-1 tine20async: real 0m0.742s
Mar 13 13:40:01 www-1 tine20async: real 0m1.003s
Mar 13 13:45:01 www-1 tine20async: real 0m1.849s
Mar 13 13:50:00 www-1 tine20async: real 0m0.699s
Mar 13 13:55:00 www-1 tine20async: real 0m0.596s
Mar 13 14:00:03 www-1 tine20async: real 0m3.037s
Mar 13 14:05:00 www-1 tine20async: real 0m0.556s
Mar 13 14:10:00 www-1 tine20async: real 0m0.956s
Mar 13 14:15:00 www-1 tine20async: real 0m0.576s
Mar 13 14:20:01 www-1 tine20async: real 0m1.048s
Mar 13 14:25:01 www-1 tine20async: real 0m1.127s
Mar 13 14:30:01 www-1 tine20async: real 0m1.413s
Mar 13 14:35:00 www-1 tine20async: real 0m0.556s
Mar 13 14:40:01 www-1 tine20async: real 0m1.333s
Mar 13 14:45:04 www-1 tine20async: real 0m4.234s
Mar 13 14:50:02 www-1 tine20async: real 0m2.464s
Mar 13 14:55:00 www-1 tine20async: real 0m0.708s
Mar 13 15:00:07 www-1 tine20async: real 0m7.882s
Mar 13 15:05:00 www-1 tine20async: real 0m0.765s
Mar 13 15:10:00 www-1 tine20async: real 0m0.749s
Mar 13 15:15:00 www-1 tine20async: real 0m0.845s
Mar 13 15:20:01 www-1 tine20async: real 0m0.992s
Mar 13 15:25:01 www-1 tine20async: real 0m1.516s
Mar 13 15:30:01 www-1 tine20async: real 0m0.987s
Mar 13 15:35:00 www-1 tine20async: real 0m0.841s
Mar 13 15:40:00 www-1 tine20async: real 0m0.954s
Mar 13 15:45:00 www-1 tine20async: real 0m0.729s
Mar 13 15:50:00 www-1 tine20async: real 0m0.716s
Mar 13 15:55:00 www-1 tine20async: real 0m0.611s
Mar 13 16:00:01 www-1 tine20async: real 0m1.609s
Mar 13 16:05:00 www-1 tine20async: real 0m0.660s
Mar 13 16:10:00 www-1 tine20async: real 0m0.642s
Mar 13 16:15:00 www-1 tine20async: real 0m0.605s
Mar 13 16:20:09 www-1 tine20async: real 0m9.541s
Mar 13 16:25:01 www-1 tine20async: real 0m1.136s
Mar 13 16:30:01 www-1 tine20async: real 0m1.804s
Mar 13 16:35:00 www-1 tine20async: real 0m0.554s
Mar 13 16:40:00 www-1 tine20async: real 0m0.508s
Mar 13 16:45:00 www-1 tine20async: real 0m0.899s
Mar 13 16:50:01 www-1 tine20async: real 0m1.851s
Mar 13 16:55:01 www-1 tine20async: real 0m1.090s
Mar 13 17:00:01 www-1 tine20async: real 0m1.483s
Mar 13 17:05:00 www-1 tine20async: real 0m0.872s
Mar 13 17:10:00 www-1 tine20async: real 0m0.658s
Mar 13 17:15:00 www-1 tine20async: real 0m0.464s
Mar 13 17:20:00 www-1 tine20async: real 0m0.608s
Mar 13 17:25:00 www-1 tine20async: real 0m0.760s
Mar 13 17:30:00 www-1 tine20async: real 0m0.958s
Mar 13 17:35:00 www-1 tine20async: real 0m0.659s
Mar 13 17:40:00 www-1 tine20async: real 0m0.647s
Mar 13 17:45:00 www-1 tine20async: real 0m0.664s
Mar 13 17:50:00 www-1 tine20async: real 0m0.927s
Mar 13 17:55:00 www-1 tine20async: real 0m0.641s
Mar 13 18:00:05 www-1 tine20async: real 0m5.344s
Mar 13 18:05:00 www-1 tine20async: real 0m0.462s
Mar 13 18:10:00 www-1 tine20async: real 0m0.779s
Mar 13 18:15:00 www-1 tine20async: real 0m0.739s
Mar 13 18:20:03 www-1 tine20async: real 0m3.392s
Mar 13 18:25:00 www-1 tine20async: real 0m0.794s
Mar 13 18:30:00 www-1 tine20async: real 0m0.702s
Mar 13 18:35:00 www-1 tine20async: real 0m0.798s
Mar 13 18:40:00 www-1 tine20async: real 0m0.668s
Mar 13 18:45:01 www-1 tine20async: real 0m1.910s
Mar 13 18:50:00 www-1 tine20async: real 0m0.637s
Mar 13 18:55:00 www-1 tine20async: real 0m0.444s
Mar 13 19:00:04 www-1 tine20async: real 0m4.556s
Mar 13 19:05:00 www-1 tine20async: real 0m0.821s
Mar 13 19:10:00 www-1 tine20async: real 0m0.725s
Mar 13 19:15:00 www-1 tine20async: real 0m0.863s
Mar 13 19:20:00 www-1 tine20async: real 0m0.658s
Mar 13 19:25:00 www-1 tine20async: real 0m0.767s
Mar 13 19:30:01 www-1 tine20async: real 0m1.071s
Mar 13 19:35:00 www-1 tine20async: real 0m0.749s
Mar 13 19:40:00 www-1 tine20async: real 0m0.613s
Mar 13 19:45:00 www-1 tine20async: real 0m0.693s
Mar 13 19:50:00 www-1 tine20async: real 0m0.651s
Mar 13 19:55:00 www-1 tine20async: real 0m0.688s
Mar 13 20:00:01 www-1 tine20async: real 0m1.571s
Mar 13 20:05:00 www-1 tine20async: real 0m0.532s
Mar 13 20:10:00 www-1 tine20async: real 0m0.596s
Mar 13 20:15:00 www-1 tine20async: real 0m0.613s
Mar 13 20:20:16 www-1 tine20async: real 0m16.349s
Mar 13 20:25:00 www-1 tine20async: real 0m0.629s
Mar 13 20:30:01 www-1 tine20async: real 0m1.427s
Mar 13 20:35:00 www-1 tine20async: real 0m0.832s
Mar 13 20:40:00 www-1 tine20async: real 0m0.637s
Mar 13 20:45:01 www-1 tine20async: real 0m1.328s
Mar 13 20:50:00 www-1 tine20async: real 0m0.846s
Mar 13 20:55:00 www-1 tine20async: real 0m0.638s
Mar 13 21:00:02 www-1 tine20async: real 0m2.071s
Mar 13 21:05:01 www-1 tine20async: real 0m1.087s
Mar 13 21:10:00 www-1 tine20async: real 0m0.591s
Mar 13 21:15:01 www-1 tine20async: real 0m0.990s
Mar 13 21:20:00 www-1 tine20async: real 0m0.742s
Mar 13 21:25:00 www-1 tine20async: real 0m0.781s
Mar 13 21:30:01 www-1 tine20async: real 0m1.263s
Mar 13 21:35:00 www-1 tine20async: real 0m0.592s
Mar 13 21:40:00 www-1 tine20async: real 0m0.643s
Mar 13 21:45:00 www-1 tine20async: real 0m0.650s
Mar 13 21:50:00 www-1 tine20async: real 0m0.953s
Mar 13 21:55:00 www-1 tine20async: real 0m0.475s
Mar 13 22:00:04 www-1 tine20async: real 0m4.089s
Mar 13 22:05:00 www-1 tine20async: real 0m0.783s
Mar 13 22:10:02 www-1 tine20async: real 0m1.908s
Mar 13 22:15:03 www-1 tine20async: real 0m3.045s
Mar 13 22:20:38 www-1 tine20async: real 0m38.767s
Mar 13 22:25:02 www-1 tine20async: real 0m2.637s
Mar 13 22:30:00 www-1 tine20async: real 0m0.800s
Mar 13 22:35:00 www-1 tine20async: real 0m0.481s
Mar 13 22:40:00 www-1 tine20async: real 0m0.498s
Mar 13 22:45:00 www-1 tine20async: real 0m0.608s
Mar 13 22:50:00 www-1 tine20async: real 0m0.806s
Mar 13 22:55:00 www-1 tine20async: real 0m0.839s
Mar 13 23:00:01 www-1 tine20async: real 0m1.692s
Mar 13 23:05:00 www-1 tine20async: real 0m0.932s
Mar 13 23:10:01 www-1 tine20async: real 0m0.971s
Mar 13 23:15:00 www-1 tine20async: real 0m0.752s
Mar 13 23:20:00 www-1 tine20async: real 0m0.728s
Mar 13 23:25:00 www-1 tine20async: real 0m0.758s
Mar 13 23:30:03 www-1 tine20async: real 0m3.251s
Mar 13 23:35:00 www-1 tine20async: real 0m0.675s
Mar 13 23:40:01 www-1 tine20async: real 0m1.063s
Mar 13 23:45:00 www-1 tine20async: real 0m0.673s
Mar 13 23:50:00 www-1 tine20async: real 0m0.659s
Mar 13 23:55:01 www-1 tine20async: real 0m1.059s
Mar 14 00:00:02 www-1 tine20async: real 0m2.309s
Mar 14 00:05:00 www-1 tine20async: real 0m0.492s
Mar 14 00:10:01 www-1 tine20async: real 0m1.028s
Mar 14 00:15:00 www-1 tine20async: real 0m0.620s
Mar 14 00:20:00 www-1 tine20async: real 0m0.718s
Mar 14 00:25:00 www-1 tine20async: real 0m0.914s
Mar 14 00:30:00 www-1 tine20async: real 0m0.621s
Mar 14 00:35:00 www-1 tine20async: real 0m0.716s
Mar 14 00:40:00 www-1 tine20async: real 0m0.771s
Mar 14 00:45:00 www-1 tine20async: real 0m0.781s
Mar 14 00:50:00 www-1 tine20async: real 0m0.851s
Mar 14 00:55:00 www-1 tine20async: real 0m0.728s
Mar 14 11:29:22 www-1 tine20async: real 629m22.249s
Mar 14 11:30:24 www-1 tine20async: real 0m24.910s
Mar 14 11:35:00 www-1 tine20async: real 0m0.706s
Mar 14 11:40:01 www-1 tine20async: real 0m1.263s
Mar 14 11:45:00 www-1 tine20async: real 0m0.626s
Mar 14 11:50:01 www-1 tine20async: real 0m1.689s
Mar 14 11:55:00 www-1 tine20async: real 0m0.628s
Mar 14 12:00:03 www-1 tine20async: real 0m3.387s
Mar 14 12:05:00 www-1 tine20async: real 0m0.936s
Mar 14 12:10:00 www-1 tine20async: real 0m0.702s
Mar 14 12:15:00 www-1 tine20async: real 0m0.630s
Mar 14 12:20:19 www-1 tine20async: real 0m19.362s

Gloirin commented Jun 11, 2018

Comment posted by bammes on 14 Mar 2018 11:28

Short analysis of what I have in my general syslog right now shows only one occurence today with 629 minutes.
I will raise the loglevel again and keep you posted.

root@www-1:~ # bzgrep tine20async /var/log/messages | grep real
Mar 13 13:05:00 www-1 tine20async: real 0m0.664s
Mar 13 13:10:00 www-1 tine20async: real 0m0.730s
Mar 13 13:15:00 www-1 tine20async: real 0m0.683s
Mar 13 13:20:01 www-1 tine20async: real 0m1.668s
Mar 13 13:25:01 www-1 tine20async: real 0m1.080s
Mar 13 13:30:01 www-1 tine20async: real 0m1.955s
Mar 13 13:35:00 www-1 tine20async: real 0m0.742s
Mar 13 13:40:01 www-1 tine20async: real 0m1.003s
Mar 13 13:45:01 www-1 tine20async: real 0m1.849s
Mar 13 13:50:00 www-1 tine20async: real 0m0.699s
Mar 13 13:55:00 www-1 tine20async: real 0m0.596s
Mar 13 14:00:03 www-1 tine20async: real 0m3.037s
Mar 13 14:05:00 www-1 tine20async: real 0m0.556s
Mar 13 14:10:00 www-1 tine20async: real 0m0.956s
Mar 13 14:15:00 www-1 tine20async: real 0m0.576s
Mar 13 14:20:01 www-1 tine20async: real 0m1.048s
Mar 13 14:25:01 www-1 tine20async: real 0m1.127s
Mar 13 14:30:01 www-1 tine20async: real 0m1.413s
Mar 13 14:35:00 www-1 tine20async: real 0m0.556s
Mar 13 14:40:01 www-1 tine20async: real 0m1.333s
Mar 13 14:45:04 www-1 tine20async: real 0m4.234s
Mar 13 14:50:02 www-1 tine20async: real 0m2.464s
Mar 13 14:55:00 www-1 tine20async: real 0m0.708s
Mar 13 15:00:07 www-1 tine20async: real 0m7.882s
Mar 13 15:05:00 www-1 tine20async: real 0m0.765s
Mar 13 15:10:00 www-1 tine20async: real 0m0.749s
Mar 13 15:15:00 www-1 tine20async: real 0m0.845s
Mar 13 15:20:01 www-1 tine20async: real 0m0.992s
Mar 13 15:25:01 www-1 tine20async: real 0m1.516s
Mar 13 15:30:01 www-1 tine20async: real 0m0.987s
Mar 13 15:35:00 www-1 tine20async: real 0m0.841s
Mar 13 15:40:00 www-1 tine20async: real 0m0.954s
Mar 13 15:45:00 www-1 tine20async: real 0m0.729s
Mar 13 15:50:00 www-1 tine20async: real 0m0.716s
Mar 13 15:55:00 www-1 tine20async: real 0m0.611s
Mar 13 16:00:01 www-1 tine20async: real 0m1.609s
Mar 13 16:05:00 www-1 tine20async: real 0m0.660s
Mar 13 16:10:00 www-1 tine20async: real 0m0.642s
Mar 13 16:15:00 www-1 tine20async: real 0m0.605s
Mar 13 16:20:09 www-1 tine20async: real 0m9.541s
Mar 13 16:25:01 www-1 tine20async: real 0m1.136s
Mar 13 16:30:01 www-1 tine20async: real 0m1.804s
Mar 13 16:35:00 www-1 tine20async: real 0m0.554s
Mar 13 16:40:00 www-1 tine20async: real 0m0.508s
Mar 13 16:45:00 www-1 tine20async: real 0m0.899s
Mar 13 16:50:01 www-1 tine20async: real 0m1.851s
Mar 13 16:55:01 www-1 tine20async: real 0m1.090s
Mar 13 17:00:01 www-1 tine20async: real 0m1.483s
Mar 13 17:05:00 www-1 tine20async: real 0m0.872s
Mar 13 17:10:00 www-1 tine20async: real 0m0.658s
Mar 13 17:15:00 www-1 tine20async: real 0m0.464s
Mar 13 17:20:00 www-1 tine20async: real 0m0.608s
Mar 13 17:25:00 www-1 tine20async: real 0m0.760s
Mar 13 17:30:00 www-1 tine20async: real 0m0.958s
Mar 13 17:35:00 www-1 tine20async: real 0m0.659s
Mar 13 17:40:00 www-1 tine20async: real 0m0.647s
Mar 13 17:45:00 www-1 tine20async: real 0m0.664s
Mar 13 17:50:00 www-1 tine20async: real 0m0.927s
Mar 13 17:55:00 www-1 tine20async: real 0m0.641s
Mar 13 18:00:05 www-1 tine20async: real 0m5.344s
Mar 13 18:05:00 www-1 tine20async: real 0m0.462s
Mar 13 18:10:00 www-1 tine20async: real 0m0.779s
Mar 13 18:15:00 www-1 tine20async: real 0m0.739s
Mar 13 18:20:03 www-1 tine20async: real 0m3.392s
Mar 13 18:25:00 www-1 tine20async: real 0m0.794s
Mar 13 18:30:00 www-1 tine20async: real 0m0.702s
Mar 13 18:35:00 www-1 tine20async: real 0m0.798s
Mar 13 18:40:00 www-1 tine20async: real 0m0.668s
Mar 13 18:45:01 www-1 tine20async: real 0m1.910s
Mar 13 18:50:00 www-1 tine20async: real 0m0.637s
Mar 13 18:55:00 www-1 tine20async: real 0m0.444s
Mar 13 19:00:04 www-1 tine20async: real 0m4.556s
Mar 13 19:05:00 www-1 tine20async: real 0m0.821s
Mar 13 19:10:00 www-1 tine20async: real 0m0.725s
Mar 13 19:15:00 www-1 tine20async: real 0m0.863s
Mar 13 19:20:00 www-1 tine20async: real 0m0.658s
Mar 13 19:25:00 www-1 tine20async: real 0m0.767s
Mar 13 19:30:01 www-1 tine20async: real 0m1.071s
Mar 13 19:35:00 www-1 tine20async: real 0m0.749s
Mar 13 19:40:00 www-1 tine20async: real 0m0.613s
Mar 13 19:45:00 www-1 tine20async: real 0m0.693s
Mar 13 19:50:00 www-1 tine20async: real 0m0.651s
Mar 13 19:55:00 www-1 tine20async: real 0m0.688s
Mar 13 20:00:01 www-1 tine20async: real 0m1.571s
Mar 13 20:05:00 www-1 tine20async: real 0m0.532s
Mar 13 20:10:00 www-1 tine20async: real 0m0.596s
Mar 13 20:15:00 www-1 tine20async: real 0m0.613s
Mar 13 20:20:16 www-1 tine20async: real 0m16.349s
Mar 13 20:25:00 www-1 tine20async: real 0m0.629s
Mar 13 20:30:01 www-1 tine20async: real 0m1.427s
Mar 13 20:35:00 www-1 tine20async: real 0m0.832s
Mar 13 20:40:00 www-1 tine20async: real 0m0.637s
Mar 13 20:45:01 www-1 tine20async: real 0m1.328s
Mar 13 20:50:00 www-1 tine20async: real 0m0.846s
Mar 13 20:55:00 www-1 tine20async: real 0m0.638s
Mar 13 21:00:02 www-1 tine20async: real 0m2.071s
Mar 13 21:05:01 www-1 tine20async: real 0m1.087s
Mar 13 21:10:00 www-1 tine20async: real 0m0.591s
Mar 13 21:15:01 www-1 tine20async: real 0m0.990s
Mar 13 21:20:00 www-1 tine20async: real 0m0.742s
Mar 13 21:25:00 www-1 tine20async: real 0m0.781s
Mar 13 21:30:01 www-1 tine20async: real 0m1.263s
Mar 13 21:35:00 www-1 tine20async: real 0m0.592s
Mar 13 21:40:00 www-1 tine20async: real 0m0.643s
Mar 13 21:45:00 www-1 tine20async: real 0m0.650s
Mar 13 21:50:00 www-1 tine20async: real 0m0.953s
Mar 13 21:55:00 www-1 tine20async: real 0m0.475s
Mar 13 22:00:04 www-1 tine20async: real 0m4.089s
Mar 13 22:05:00 www-1 tine20async: real 0m0.783s
Mar 13 22:10:02 www-1 tine20async: real 0m1.908s
Mar 13 22:15:03 www-1 tine20async: real 0m3.045s
Mar 13 22:20:38 www-1 tine20async: real 0m38.767s
Mar 13 22:25:02 www-1 tine20async: real 0m2.637s
Mar 13 22:30:00 www-1 tine20async: real 0m0.800s
Mar 13 22:35:00 www-1 tine20async: real 0m0.481s
Mar 13 22:40:00 www-1 tine20async: real 0m0.498s
Mar 13 22:45:00 www-1 tine20async: real 0m0.608s
Mar 13 22:50:00 www-1 tine20async: real 0m0.806s
Mar 13 22:55:00 www-1 tine20async: real 0m0.839s
Mar 13 23:00:01 www-1 tine20async: real 0m1.692s
Mar 13 23:05:00 www-1 tine20async: real 0m0.932s
Mar 13 23:10:01 www-1 tine20async: real 0m0.971s
Mar 13 23:15:00 www-1 tine20async: real 0m0.752s
Mar 13 23:20:00 www-1 tine20async: real 0m0.728s
Mar 13 23:25:00 www-1 tine20async: real 0m0.758s
Mar 13 23:30:03 www-1 tine20async: real 0m3.251s
Mar 13 23:35:00 www-1 tine20async: real 0m0.675s
Mar 13 23:40:01 www-1 tine20async: real 0m1.063s
Mar 13 23:45:00 www-1 tine20async: real 0m0.673s
Mar 13 23:50:00 www-1 tine20async: real 0m0.659s
Mar 13 23:55:01 www-1 tine20async: real 0m1.059s
Mar 14 00:00:02 www-1 tine20async: real 0m2.309s
Mar 14 00:05:00 www-1 tine20async: real 0m0.492s
Mar 14 00:10:01 www-1 tine20async: real 0m1.028s
Mar 14 00:15:00 www-1 tine20async: real 0m0.620s
Mar 14 00:20:00 www-1 tine20async: real 0m0.718s
Mar 14 00:25:00 www-1 tine20async: real 0m0.914s
Mar 14 00:30:00 www-1 tine20async: real 0m0.621s
Mar 14 00:35:00 www-1 tine20async: real 0m0.716s
Mar 14 00:40:00 www-1 tine20async: real 0m0.771s
Mar 14 00:45:00 www-1 tine20async: real 0m0.781s
Mar 14 00:50:00 www-1 tine20async: real 0m0.851s
Mar 14 00:55:00 www-1 tine20async: real 0m0.728s
Mar 14 11:29:22 www-1 tine20async: real 629m22.249s
Mar 14 11:30:24 www-1 tine20async: real 0m24.910s
Mar 14 11:35:00 www-1 tine20async: real 0m0.706s
Mar 14 11:40:01 www-1 tine20async: real 0m1.263s
Mar 14 11:45:00 www-1 tine20async: real 0m0.626s
Mar 14 11:50:01 www-1 tine20async: real 0m1.689s
Mar 14 11:55:00 www-1 tine20async: real 0m0.628s
Mar 14 12:00:03 www-1 tine20async: real 0m3.387s
Mar 14 12:05:00 www-1 tine20async: real 0m0.936s
Mar 14 12:10:00 www-1 tine20async: real 0m0.702s
Mar 14 12:15:00 www-1 tine20async: real 0m0.630s
Mar 14 12:20:19 www-1 tine20async: real 0m19.362s

@Gloirin

This comment has been minimized.

Show comment
Hide comment
@Gloirin

Gloirin Jun 11, 2018

Comment posted by bammes on 21 Mar 2018 17:23

Got something:

Mar 21 00:50:00 www-1 tine20async: real 0m0.578s
Mar 21 00:55:00 www-1 tine20async: real 0m0.665s
Mar 21 11:52:55 www-1 tine20async: real 652m55.814s
Mar 21 11:55:14 www-1 tine20async: real 0m14.493s

Beginning of this issue already rotated by logrotate, but I got at least something of the ongoing task in the attached log.

Gloirin commented Jun 11, 2018

Comment posted by bammes on 21 Mar 2018 17:23

Got something:

Mar 21 00:50:00 www-1 tine20async: real 0m0.578s
Mar 21 00:55:00 www-1 tine20async: real 0m0.665s
Mar 21 11:52:55 www-1 tine20async: real 652m55.814s
Mar 21 11:55:14 www-1 tine20async: real 0m14.493s

Beginning of this issue already rotated by logrotate, but I got at least something of the ongoing task in the attached log.

@Gloirin

This comment has been minimized.

Show comment
Hide comment
@Gloirin

Gloirin Jun 11, 2018

Comment posted by pmehrer on 29 Mar 2018 15:36

Hello,

the long running task:
Mar 21 11:52:55 www-1 tine20async: real 652m55.814s
started on Mar 21 00:00:00 (that makes sense, all the daily jobs are executed at midnight, they may take a while, though not 10 hours of course)

in the log file you send I can't see anything related to that. Interessting would be the time from 00:00:00 to ... wherever the job gets stuck (I would assume we should see something within the first 15 minutes or so) Do you still have the logs from Mar 21?

thanks for providing information on this issue

Gloirin commented Jun 11, 2018

Comment posted by pmehrer on 29 Mar 2018 15:36

Hello,

the long running task:
Mar 21 11:52:55 www-1 tine20async: real 652m55.814s
started on Mar 21 00:00:00 (that makes sense, all the daily jobs are executed at midnight, they may take a while, though not 10 hours of course)

in the log file you send I can't see anything related to that. Interessting would be the time from 00:00:00 to ... wherever the job gets stuck (I would assume we should see something within the first 15 minutes or so) Do you still have the logs from Mar 21?

thanks for providing information on this issue

@Gloirin

This comment has been minimized.

Show comment
Hide comment
@Gloirin

Gloirin Jun 11, 2018

Comment posted by bammes on 5 Apr 2018 18:45

Hi,

I pasted everything I got, since I worked around this problem, my monitoring system does not complain about php eating all my memory. So I have to look in the logs from time to time and very often, the relevant logs have been rotated out.

But if you have a look on the list of jobs I posted before my last post, you can clearly see, that no all of these long-running jobs happen at midnight:

Mar 14 00:55:00 www-1 tine20async: real 0m0.728s
Mar 14 11:29:22 www-1 tine20async: real 629m22.249s
Mar 14 11:30:24 www-1 tine20async: real 0m24.910s

I will keep my eyes open and hope to catch another occurence of this bug with full log...

Gloirin commented Jun 11, 2018

Comment posted by bammes on 5 Apr 2018 18:45

Hi,

I pasted everything I got, since I worked around this problem, my monitoring system does not complain about php eating all my memory. So I have to look in the logs from time to time and very often, the relevant logs have been rotated out.

But if you have a look on the list of jobs I posted before my last post, you can clearly see, that no all of these long-running jobs happen at midnight:

Mar 14 00:55:00 www-1 tine20async: real 0m0.728s
Mar 14 11:29:22 www-1 tine20async: real 629m22.249s
Mar 14 11:30:24 www-1 tine20async: real 0m24.910s

I will keep my eyes open and hope to catch another occurence of this bug with full log...

@Gloirin

This comment has been minimized.

Show comment
Hide comment
@Gloirin

Gloirin Jun 11, 2018

Comment posted by pmehrer on 19 Apr 2018 18:31

Hi,

they do happen at midnight:

Mar 14 11:29:22 www-1 tine20async: real 629m22.249s
it started exactly 6 hours 29 minutes and 22 seconds ago (that should be midnight or 1pm or a like)

so the interessting log is not Mar 14 11:29, the interessting log is Mar 14 01:00 to Mar 14 01:15 if I can get that, I can help you.

Gloirin commented Jun 11, 2018

Comment posted by pmehrer on 19 Apr 2018 18:31

Hi,

they do happen at midnight:

Mar 14 11:29:22 www-1 tine20async: real 629m22.249s
it started exactly 6 hours 29 minutes and 22 seconds ago (that should be midnight or 1pm or a like)

so the interessting log is not Mar 14 11:29, the interessting log is Mar 14 01:00 to Mar 14 01:15 if I can get that, I can help you.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment