No analytics play counts - dwh_plays_views_sync error - Couldn't find entry

Community Forums Backend Server Support
1

A client’s kaltura 11.1.0-2 installation is failing to update play counts in analytics - yet the uploads/storage details etc are fine.

I’ve checked all the etl dwh logs, which seem to be fine.

However the dwh_plays_views_sync has an error:

su - kaltura -c '/opt/kaltura/app/alpha/scripts/dwh/dwh_plays_views_sync.sh’
Fri Jan 15 11:01:58 NZDT 2016
start dwh triggers
2016-01-15 11:01:58 [require_once] INFO: Starting script
2016-01-15 11:01:58 [require_once] INFO: Initializing database…
2016-01-15 11:01:58 [require_once] INFO: Database initialized successfully
2016-01-15 11:01:58 [KalturaPDO->__construct] DEBUG: conn took - 0.047573089599609 seconds to mysql:host=localhost;port=3306;dbname=kaltura;
2016-01-15 11:01:58 [Propel::initConnection] NOTICE: total conn took 0.051308155059814 mysql:host=localhost;port=3306;dbname=kaltura;
2016-01-15 11:01:58 [KalturaStatement->execute] DEBUG: /* [798611602][propel] */ SELECT entry.ID, entry.KSHOW_ID, entry.KUSER_ID, entry.NAME, entry.TYPE, entry.MEDIA_TYPE, entry.DATA, entry.THUMBNAIL, entry.VIEWS, entry.VOTES, entry.COMMENTS, entry.FAVORITES, entry.TOTAL_RANK, entry.RANK, entry.TAGS, entry.ANONYMOUS, entry.STATUS, entry.SOURCE, entry.SOURCE_ID, entry.SOURCE_LINK, entry.LICENSE_TYPE, entry.CREDIT, entry.LENGTH_IN_MSECS, entry.CREATED_AT, entry.UPDATED_AT, entry.PARTNER_ID, entry.DISPLAY_IN_SEARCH, entry.SUBP_ID, entry.CUSTOM_DATA, entry.SCREEN_NAME, entry.SITE_URL, entry.PERMISSIONS, entry.GROUP_ID, entry.PLAYS, entry.PARTNER_DATA, entry.INT_ID, entry.INDEXED_CUSTOM_DATA_1, entry.DESCRIPTION, entry.MEDIA_DATE, entry.ADMIN_TAGS, entry.MODERATION_STATUS, entry.MODERATION_COUNT, entry.MODIFIED_AT, entry.PUSER_ID, entry.ACCESS_CONTROL_ID, entry.CONVERSION_PROFILE_ID, entry.CATEGORIES, entry.CATEGORIES_IDS, entry.START_DATE, entry.END_DATE, entry.FLAVOR_PARAMS_IDS, entry.AVAILABLE_FROM, entry.LAST_PLAYED_AT FROM entry WHERE entry.ID=‘0_nh8lh82p’ AND entry.STATUS<>'3’
2016-01-15 11:01:58 [KalturaStatement->execute] DEBUG: Sql took - 0.0010969638824463 seconds
2016-01-15 11:01:58 [global] ERR: exception ‘Exception’ with message ‘Couldn’t find entry [0_nh8lh82p]’ in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/scripts/dwh/updateEntryPlaysViews.php(19): KalturaLog::err(‘Couldn’t find e…’)
#1 {main}
start dwh wrap
end dwh

It seems like there’s some disconnect between the entry IDs. Looking in the content view of KMC I certainly can’t see any media with an id like that.

Any ideas how to solve this? Do I need to wipe the analytics db and recreate (as in the FAQ)? Or is there something else I can do?

Cheers!

2

Hello,

That would usually indicate that the operational DB [MySQL] is not synced with the Sphinx instance, or instances.
Start by checking the entry status in the DB with:
mysql> select status from kaltura.entry where id=‘0_nh8lh82p’;

For an entry in status ready, the value should be 2.

If it is indeed 2 and you do not see it in KMC, try reindexing the entries. You can do so by running:
# /opt/kaltura/bin/kaltura-sphinx-reindex.sh

3

Hi Jess,

Thanks for that. Status is ‘3’. I notice the script is specifically looking for entries with status <> 3 - I believe 3 == deleted? In which case there is certainly seems like some disconnect between the two datasets. Should I perform a sphinx reindex anyway?

Having a look through the sphinx logs for errors, only two warnings:

[Mon Jan 18 10:19:51.572 2016] [ 918] caught SIGTERM, shutting down
[Mon Jan 18 10:19:51.661 2016] [ 918] rt: index kaltura_entry: ramchunk saved in 0.053 sec
[Mon Jan 18 10:19:51.662 2016] [ 918] rt: index kaltura_category: ramchunk saved in 0.001 sec
[Mon Jan 18 10:19:51.664 2016] [ 918] rt: index kaltura_kuser: ramchunk saved in 0.001 sec
[Mon Jan 18 10:19:51.666 2016] [ 918] rt: index kaltura_category_kuser: ramchunk saved in 0.001 sec
[Mon Jan 18 10:19:51.667 2016] [ 918] rt: index kaltura_cue_point: ramchunk saved in 0.001 sec
[Mon Jan 18 10:19:51.668 2016] [ 918] rt: index kaltura_entry_distribution: ramchunk saved in 0.001 sec
[Mon Jan 18 10:19:51.669 2016] [ 918] rt: index kaltura_caption_item: ramchunk saved in 0.001 sec
[Mon Jan 18 10:19:51.772 2016] [ 918] rt: index kaltura_tag: ramchunk saved in 0.101 sec
[Mon Jan 18 10:19:51.773 2016] [ 918] rt: index kaltura_metadata: ramchunk saved in 0.001 sec
[Mon Jan 18 10:19:51.773 2016] [ 918] shutdown complete
[Mon Jan 18 10:19:51.776 2016] [ 917] Child process 918 has been finished, exit code 0. Watchdog finishes also. Good bye!
[Mon Jan 18 10:19:52.226 2016] [25722] Child process 25723 has been forked
[Mon Jan 18 10:19:52.233 2016] [25723] listening on all interfaces, port=9312
[Mon Jan 18 10:19:52.233 2016] [25723] WARNING: index ‘kaltura_base’: no fields configured (use rt_field directive) - NOT SERVING
[Mon Jan 18 10:19:52.233 2016] [25723] WARNING: index ‘kaltura_kuser_base’: no fields configured (use rt_field directive) - NOT SERVING
[Mon Jan 18 10:19:52.289 2016] [25723] accepting connections

I’ve tried to dpkg-reconfigure kaltura-sphinx in case that fixed something, no dice.

Any ideas?

Cheers!

4

Hello,

dpkg-reconfigure won’t help you where it comes to sync issues.
Start by getting the int ID for the entry like so:
mysql> select status,int_id from entry where id=’’\G
*************************** 1. row ***************************
status: 7
int_id: 1868

and then connect to sphinx:
# mysql -h127.0.0.1 -P9312
and:
mysql> select entry_status from kaltura_entry where id=1868\G
*************************** 1. row ***************************
entry_status: 7

In this example, since I do not have sync issues, they match, if in your case, they do not, it would be a good time to reindex:)

5

Hrm, the query into the sphinx database produces an empty result set. I wonder where the knowledge of the deleted entry is? I can’t quite grok the code run from dwh_plays_views_sync.sh

I’ve tried a sphinx reindex and it hasn’t helped.

6

Hello,

So, let me explain a bit about this script and what it does:
First off, it’s goal is to sync the ‘plays’ from the DWH DB into the operation DB, this affects the “Plays” field displayed in the KMC->Content tab but should not affect the data you see in the Analytics tab.

And so, if the issue is more than the plays in the content tab, take a look at:

Assuming the issue is ONLY with the plays in the content tab, the script calls a stored procedure defined here:
/opt/kaltura/dwh/ddl/dw/functions/get_data_for_operational.sql

It would run this code:
SELECT e.entry_id, e.plays, e.views
FROM dwh_entry_plays_views e, kalturadw_ds.parameters p
WHERE e.updated_at > p.date_value AND p.id = 4;

And then, for each such entry, an attempt to set the plays will be done by calling:
php $BASE_DIR/app/alpha/scripts/dwh/updateEntryPlaysViews.php

So, if somehow, you have 0_nh8lh82p in the DWH DB and not in Sphinx, it would fail. However, this should not interfere with doing the other entries.

Hope this helps,

7

Hello @jess

Analytics dosen’t work.
How can I do?

log_storage_usage_calc_storage_usage.log:2016/01/22 08:41:18 - Execute SQL script.0 - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Error while running this step!
log_storage_usage_calc_storage_usage.log:2016/01/22 08:41:18 - Execute SQL script.0 - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:998)
log_storage_usage_calc_storage_usage.log:2016/01/22 08:41:18 - Execute SQL script.0 - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3835)
log_storage_usage_calc_storage_usage.log:2016/01/22 08:41:18 - Execute SQL script.0 - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3771)
log_storage_usage_calc_storage_usage.log:2016/01/22 08:41:18 - calc_storage_usage - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Errors detected!
log_storage_usage_calc_storage_usage.log:2016/01/22 08:41:18 - calc_storage_usage - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Errors detected!
log_storage_usage_calc_storage_usage.log:2016/01/22 08:56:54 - Execute SQL script.0 - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Error while running this step!
log_storage_usage_calc_storage_usage.log:2016/01/22 08:56:54 - Execute SQL script.0 - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:998)
log_storage_usage_calc_storage_usage.log:2016/01/22 08:56:54 - Execute SQL script.0 - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3835)
log_storage_usage_calc_storage_usage.log:2016/01/22 08:56:54 - Execute SQL script.0 - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3771)
log_storage_usage_calc_storage_usage.log:2016/01/22 08:56:54 - calc_storage_usage - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Errors detected!
8

Hello,

More info is needed. Look at the lines leading up to the final error to understand what exactly is failing.
If needed, post them here.
Also, please open a separate thread because, while both issues are about analytics, they are quite different and unrelated.

Thanks,