Analytics: "plays" count not working

1

Hello, I’m a beginner about kaltura server, and installed on totally new GCP instance using CentOS6, according to the document of the installation for redhat based systems.

I’ve got kaltura server running and video distribution is working fine, but analytics… DWH packages are not at all.
I’ve already tried so many times other system (CentOS7, ubuntu 16.04, etc…), but never worked. NEVER!

below is log of kaltura-sanity.sh. “DWH cycle” check always fails.

INSERT INTO csi_log VALUES(NULL,'Space on /opt/kaltura','435c85d0850d',1539190050,"Good - /opt/kaltura has  free space [35243752]",0,.035303315,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Space on /opt/kaltura/web','435c85d0850d',1539190050,"Good - /opt/kaltura/web has  free space [35243748]",0,.009371823,'14.5.0'
);
INSERT INTO csi_log VALUES(NULL,'Check httpd daemon status','435c85d0850d',1539190071,"Daemon httpd is running",0,.040765290,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Check httpd daemon is started by Monit','435c85d0850d',1539190084,"Daemon httpd is running",0,11.950643401,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check daemon httpd init status','435c85d0850d',1539190084,"Daemon httpd configured to run on init.",0,.026185196,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Check kaltura-sphinx daemon status','435c85d0850d',1539190085,"Daemon kaltura-sphinx is running",0,.049089776,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Check kaltura-sphinx daemon is started by Monit','435c85d0850d',1539190097,"Daemon kaltura-sphinx is running",0,10.807046925,'1
4.5.0');
INSERT INTO csi_log VALUES(NULL,'check daemon kaltura-sphinx init status','435c85d0850d',1539190097,"Daemon kaltura-sphinx configured to run on init.",0,.012329
272,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Check kaltura-batch daemon status','435c85d0850d',1539190098,"Daemon kaltura-batch is running",0,.071676379,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Check kaltura-batch daemon is started by Monit','435c85d0850d',1539190100,"Daemon kaltura-batch is running",0,1.275236491,'14.5
.0');
INSERT INTO csi_log VALUES(NULL,'check daemon kaltura-batch init status','435c85d0850d',1539190101,"Daemon kaltura-batch configured to run on init.",0,.00884792
4,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Check kaltura-monit daemon status','435c85d0850d',1539190102,"Daemon kaltura-monit is running",0,.044452527,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check daemon kaltura-monit init status','435c85d0850d',1539190103,"Daemon kaltura-monit configured to run on init.",0,.03008828
6,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Check memcached daemon status','435c85d0850d',1539190104,"Daemon memcached is running",0,.131700420,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Check memcached daemon is started by Monit','435c85d0850d',1539190106,"Daemon memcached is running",0,1.322121703,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check daemon memcached init status','435c85d0850d',1539190107,"Daemon memcached configured to run on init.",0,.008669102,'14.5.
0');
INSERT INTO csi_log VALUES(NULL,'kaltura-html5lib ver in KMC config.ini','435c85d0850d',1539190108,"kaltura-html5lib v2.71.2 found in /opt/kaltura/web/flash/kmc
/v5.43.13/config.ini",0,.127562304,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'kaltura-kdp3 ver in KDP3 config.ini','435c85d0850d',1539190109,"kaltura-kdp3 v3.9.9 found in /opt/kaltura/web/flash/kmc/v5.43.1
3/config.ini",0,.066683055,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'kaltura-kmc ver in KMC config.ini','435c85d0850d',1539190110,"kaltura-kmc v5.43.13 found in /opt/kaltura/web/flash/kmc/v5.43.13
/config.ini",0,.107717276,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Get KMC SWFs','435c85d0850d',1539190111,"Content returned for [https://mov.blessllc.com//flash/kmc/login/v1.2.9/login.swf]
content type for https://mov.blessllc.com//flash/kmc/login/v1.2.9/login.swf is Flash SWF as expected.
Content returned for [https://mov.blessllc.com//flash/kmc/v5.43.13/kmc.swf]
content type for https://mov.blessllc.com//flash/kmc/v5.43.13/kmc.swf is Flash SWF as expected.",0,.666171397,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check_start_page','435c85d0850d',1539190112,"Successfully found "Kaltura Platform Start Page - Getting Started" on page https://mov.blessllc.com/start/index.php",0,.248940470,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check_testme_page','435c85d0850d',1539190113,"Successfully found 'Kaltura - Test Me Console' on page https://mov.blessllc.com/api_v3/testme/",0,.266298459,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check_kmc_index_page','435c85d0850d',1539190114,"Successfully found 'Kaltura - Open Source Video Platform'",0,.153931344,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check_admin_console_index_page','435c85d0850d',1539190116,"Successfully found 'Kaltura Admin Console' on page https://mov.blessllc.com/admin_console/",0,.675939456,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check_studio_index_page','435c85d0850d',1539190117,"Successfully found 'Universal Studio'",0,.293532831,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'check_clipapp_index_page','435c85d0850d',1539190119,"Successfully found 'Invalid partner id'",0,.960432522,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Create Partner','435c85d0850d',1539190123,"New PID is 103",0,4.061219843,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Local dropfolder creation','435c85d0850d',1539190125,"'sanity_drop successfully created for partner:103",0,1.227660870,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Create flavor param','435c85d0850d',1539190127,"112",0,1.222100159,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Delete flavor param','435c85d0850d',1539190129,"112",0,.713750099,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'HTTP notification: ID: 26, URL: http://localhost/1.php','435c85d0850d',1539190132,"ID: 26, URL: http://localhost/1.php",0,1.222100159,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Mail notification: ID: 27, Subject: Your video is ready to be played!, Mail body: Hello world:)^M','435c85d0850d',1539190134,"ID: 27, Subject: Your video is ready to be played!, Mail body: Hello world:)^M",0,1.222100159,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Upload content kaltura_logo_animated_blue.flv','435c85d0850d',1539190137,"0_bj29m2fn",0,2.021675112,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'kaltura_logo_animated_blue.flv - 0_bj29m2fn status','435c85d0850d',1539190238,"0_bj29m2fn failed to convert.",1,-.623876437,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Found an email sending entry for mb-435c85d0850d@kaltura.com[PID is 103] in /var/log/maillog','435c85d0850d',1539190268,"Oct 11 01:49:59 435c85d0850d postfix/smtp[21554]: 72F6B115FC: to=<mb-435c85d0850d@kaltura.com>, relay=smtp.sendgrid.net[161.202.148.160]:2525, delay=0.24, delays=0.14/0/0.05/0.05, dsn=2.0.0, status=sent (250 Ok: queued as 7Yea-YULQ0CGV3wUVste4Q)
Oct 11 01:50:38 435c85d0850d postfix/smtp[21554]: 6642F115EF: to=<mb-435c85d0850d@kaltura.com>, relay=smtp.sendgrid.net[161.202.148.160]:2525, delay=0.08, delays=0.01/0/0.05/0.01, dsn=2.0.0, status=sent (250 Ok: queued as 8-s5nwuSTQuTP6rSfwr1hw)",0,30.038591340,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'DWH cycle','435c85d0850d',1539190508,"Sent event [KalturaStatsEventType::WIDGET_LOADED] Sent event [KalturaStatsEventType::MEDIA_LOADED] Sent event [KalturaStatsEventType::PLAY] Sent event [KalturaStatsEventType::PLAY_REACHED_25] Sent event [KalturaStatsEventType::PLAY_REACHED_50] Sent event [KalturaStatsEventType::PLAY_REACHED_75] Sent event [KalturaStatsEventType::PLAY_REACHED_100] Executing [logrotate -f /etc/logrotate.d/kaltura_apache]error: /etc/logrotate.d/kaltura_apache:12 unknown option su -- ignoring line error: /etc/logrotate.d/kaltura_apache:12 unexpected text error: /etc/logrotate.d/kaltura_apache:26 unknown option su -- ignoring line error: /etc/logrotate.d/kaltura_apache:26 unexpected text error: /etc/logrotate.d/kaltura_apache:40 unknown option su -- ignoring line error: /etc/logrotate.d/kaltura_apache:40 unexpected text error: /etc/logrotate.d/kaltura_apache:54 unknown option su -- ignoring line error: /etc/logrotate.d/kaltura_apache:54 unexpected text Reloading httpd: log rotated Executing [su kaltura -c /opt/kaltura/dwh/etlsource/execute/etl_hourly.sh -p /opt/kaltura/dwh -k /opt/kaltura/pentaho/pdi/kitchen.sh ] OK Executing [su kaltura -c /opt/kaltura/dwh/etlsource/execute/etl_update_dims.sh -p /opt/kaltura/dwh -k /opt/kaltura/pentaho/pdi/kitchen.sh] OK Executing [su kaltura -c /opt/kaltura/dwh/etlsource/execute/etl_daily.sh -p /opt/kaltura/dwh -k /opt/kaltura/pentaho/pdi/kitchen.sh] OK Reported wrong total count []",255,119.440756163,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Upload content kaltura_logo_animated_green.flv','435c85d0850d',1539190511,"0_v6xe2nn4",0,1.720902222,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Upload bulk using CSV','435c85d0850d',1539190513,"Successfully uploaded",0,1.403193009,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Upload bulk using XML','435c85d0850d',1539190514,"Successfully uploaded",0,.816522100,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Create player','435c85d0850d',1539190515,"Generated UI conf id : 23448173",0,.621081735,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Generate thumb','435c85d0850d',1539190517,"Thumb ID 0_8wj8nsdg was generated",0,.700000826,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Delete all entries','435c85d0850d',1539190519,"Entries for partner 103 deleted successfully.",0,.979726235,'14.5.0');
INSERT INTO csi_log VALUES(NULL,'Delete partner','435c85d0850d',1539190521,"Partner [103] deleted",0,1.389582057,'14.5.0');
2

this log is produced on the case of installation by docker. kaltura’s docker image uses CentOS6, and when I tried installation directly on CentOS6 instance without docker, it has almost same pattern of sanity log.

3

Hi @zvorak.

The DWH sanity check often fails due to timing issues but that does not necessarily mean there’s an actual problem.
Can you please go through the checks here:

and let me know as to the results?
Note also that the analytics stats are not updated in real time but rather on daily basis and that plays done in KMC context are not counted.

4

@jess thank you for response.
according to the document, describe the status of my circumstances.

  1. ‘locks’ table

    mysql> select * from kalturadw_ds.locks ;
    ±--------±--------------------±--------------------±-----------+
    | lock_id | lock_name | lock_time | lock_state |
    ±--------±--------------------±--------------------±-----------+
    | 1 | hourly_435c85d0850d | 2018-10-11 05:11:40 | 0 |
    | 2 | retention_lock | 2018-10-11 12:30:25 | 0 |
    ±--------±--------------------±--------------------±-----------+
    2 rows in set (0.00 sec)

  2. ‘files’ table

    mysql> select * from kalturadw_ds.files;
    ±--------±-------------------------------------------------------±------------±------------±--------------------±---------±--------------±------±----------±-------------±-----------±---------±-------------------±-------+
    | file_id | file_name | file_status | prev_status | insert_time | run_time | transfer_time | lines | err_lines | file_size_kb | process_id | cycle_id | compression_suffix | subdir |
    ±--------±-------------------------------------------------------±------------±------------±--------------------±---------±--------------±------±----------±-------------±-----------±---------±-------------------±-------+
    | 1 | 435c85d0850d-kaltura_apache_access_ssl.log-20181011-01 | IN_CYCLE | NULL | 2018-10-11 01:53:43 | NULL | NULL | NULL | NULL | 8 | 1 | 1 | gz | |
    | 2 | 435c85d0850d-kaltura_apache_access.log-20181011-04 | IN_CYCLE | NULL | 2018-10-11 05:00:42 | NULL | NULL | NULL | NULL | 0 | 1 | 2 | gz | |
    | 3 | 435c85d0850d-kaltura_apache_access_ssl.log-20181011-04 | IN_CYCLE | NULL | 2018-10-11 05:00:42 | NULL | NULL | NULL | NULL | 121 | 1 | 2 | gz | |
    ±--------±-------------------------------------------------------±------------±------------±--------------------±---------±--------------±------±----------±-------------±-----------±---------±-------------------±-------+
    3 rows in set (0.02 sec)

  3. ‘dwh_fact_events’ table

    ±--------±---------±--------------±---------------±--------------------±--------------±--------------±-------------------------------------±-----------±-----------±--------------±----------±-----------±-----±--------------±---------±----------------±---------------±-----------±------------±-----------------±-----------±-----±----------±----------±--------------------±-----------------±------------±------±-----------±-----------±--------±---------------+
    | file_id | event_id | event_type_id | client_version | event_time | event_date_id | event_hour_id | session_id | partner_id | entry_id | unique_viewer | widget_id | ui_conf_id | uid | current_point | duration | user_ip | user_ip_number | country_id | location_id | process_duration | control_id | seek | new_point | domain_id | entry_media_type_id | entry_partner_id | referrer_id | os_id | browser_id | context_id | user_id | application_id |
    ±--------±---------±--------------±---------------±--------------------±--------------±--------------±-------------------------------------±-----------±-----------±--------------±----------±-----------±-----±--------------±---------±----------------±---------------±-----------±------------±-----------------±-----------±-----±----------±----------±--------------------±-----------------±------------±------±-----------±-----------±--------±---------------+
    | 3 | 5584 | 2 | 2.71.2 | 2018-10-11 04:29:41 | 20181011 | 4 | bc1a123f-b897-5693-df53-d37ca7dc6148 | 102 | 0_8a7wa7gk | | _102 | 23448125 | | 0 | 0 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 1 | 1 | 1 | -1 | 2 | 0 |
    | 3 | 5601 | 2 | 2.71.2 | 2018-10-11 04:29:44 | 20181011 | 4 | e74ad85f-8921-4ec4-a126-5380bdae962d | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 0 | 0 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 1 | 1 | 1 | -1 | 2 | 0 |
    | 3 | 5618 | 2 | 2.71.2 | 2018-10-11 04:29:48 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 0 | 0 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5625 | 3 | 2.71.2 | 2018-10-11 04:29:51 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 0 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5627 | 4 | 2.71.2 | 2018-10-11 04:29:51 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 506 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5629 | 17 | 2.71.2 | 2018-10-11 04:29:52 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 1002 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5630 | 5 | 2.71.2 | 2018-10-11 04:29:52 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 1004 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5632 | 6 | 2.71.2 | 2018-10-11 04:29:52 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 1744 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5634 | 7 | 2.71.2 | 2018-10-11 04:29:53 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102
    | 0_8a7wa7gk | | _102 | 23448171 | | 1995 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5638 | 16 | 2.71.2 | 2018-10-11 04:29:54 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 10 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5639 | 17 | 2.71.2 | 2018-10-11 04:29:54 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 0 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5643 | 16 | 2.71.2 | 2018-10-11 04:29:56 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 10 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    | 3 | 5648 | 16 | 2.71.2 | 2018-10-11 04:29:59 | 20181011 | 4 | 69ede276-8d6c-b321-e743-8aa3e74d1461 | 102 | 0_8a7wa7gk | | _102 | 23448171 | | 10 | 2 | 119.173.203.182 | 2007878582 | 45 | 45 | 0 | -1 | 0 | -1 | 1 | -1 | -1 | 2 | 1 | 1 | -1 | 0 | 0 |
    ±--------±---------±--------------±---------------±--------------------±--------------±--------------±-------------------------------------±-----------±-----------±--------------±----------±-----------±-----±--------------±---------±----------------±---------------±-----------±------------±-----------------±-----------±-----±----------±----------±--------------------±-----------------±------------±------±-----------±-----------±--------±---------------+
    13 rows in set (0.00 sec)

and I’ve now checked dwh_plays_views_sync.sh behavior.

mysql -h$DWH_HOST -P$DWH_PORT -u$DWH_USER -p$DWH_PASS < $BASE_DIR/app/alpha/scripts/dwh/trigger.sql

nothing outputed.

5

Hi @zvorak,

So, I see there are events recorded for 0_8a7wa7gk today.
These should show in KMC under analytics soon.
If you wish to manually run the DWH scripts configured here:
/etc/cron.d/kaltura-dwh

you can execute:

# /opt/kaltura/bin/kaltura-run-dwh.sh

If, after doing so, you still don’t see the events, please check the logs under /opt/kaltura/dwh/logs for erroneous patterns and paste them here.

6

@jess I’ve runned kaltura-run-dwh.sh script with “rowlevel”. here is etl_hourly.log picked up ERROR output.

DEBUG 11-10 21:31:33,115 - Get free lock - Found result after database lookup: [Ljava.lang.Object;@7b6c5d72
DEBUG 11-10 21:31:33,116 - Register lock - Signaling 'output done' to 1 output rowsets.
DEBUG 11-10 21:31:33,116 - kalturadw_ds - Commit on database connection [kalturadw_ds]
DEBUG 11-10 21:31:33,117 - Lock is free - Sending row to true  :Get Now : [435c85d0850d], [hourly_], [hourly_435c85d0850d], [1], [0], [1]
DEBUG 11-10 21:31:33,118 - Get Now - System info returned: [435c85d0850d], [hourly_], [hourly_435c85d0850d], [1], [0], [1], [2018/10/11 21:31:32.567]
INFO  11-10 21:31:33,123 - Seize lock - Checking row: [435c85d0850d], [hourly_], [hourly_435c85d0850d], [1], [0], [1], [2018/10/11 21:31:32.567]
DEBUG 11-10 21:31:33,123 - Seize lock - Field [lock_name] has nr. 2
DEBUG 11-10 21:31:33,123 - Seize lock - Field [FREE_STATE] has nr. 4
DEBUG 11-10 21:31:33,123 - Seize lock - Field [LOCKED_STATE] has nr. 3
DEBUG 11-10 21:31:33,123 - Seize lock - Field [now] has nr. 6
INFO  11-10 21:31:33,123 - Seize lock - Setting preparedStatement to [SELECT lock_state, lock_time FROM locks WHERE  ( ( lock_name = ?  ) )  AND  ( ( lock_state
 = ?  ) ) ]
INFO  11-10 21:31:33,124 - Seize lock - Setting update preparedStatement to [UPDATE locks
SET lock_state = ?
,   lock_time = ?
WHERE  ( ( lock_name = ?  ) ) AND    ( ( lock_state = ?  ) ) ]
DEBUG 11-10 21:31:33,125 - Seize lock - Values set for lookup: [hourly_435c85d0850d], [0], input row: [435c85d0850d], [hourly_], [hourly_435c85d0850d], [1], [0]
, [1], [2018/10/11 21:31:32.567]
DEBUG 11-10 21:31:33,125 - kalturadw_ds - Commit on database connection [kalturadw_ds]
INFO  11-10 21:31:33,133 - kalturadw_ds - Connection to database closed!
INFO  11-10 21:31:33,133 - Register lock - Finished processing (I=1, O=0, R=1, W=1, U=0, E=0)
ERROR 11-10 21:31:33,133 - Seize lock - Error in step, asking everyone to stop because of:
ERROR 11-10 21:31:33,133 - Seize lock - org.pentaho.di.core.exception.KettleValueException: 
LOCKED_STATE Integer : There was a data type error: the data type of java.lang.Boolean object [false] does not correspond to value meta [Integer]

        at org.pentaho.di.core.row.ValueMeta.getString(ValueMeta.java:1358)
        at org.pentaho.di.core.row.RowMeta.getString(RowMeta.java:184)
        at org.pentaho.di.core.row.RowMeta.getString(RowMeta.java:605)
        at org.pentaho.di.trans.steps.update.Update.lookupValues(Update.java:137)
        at org.pentaho.di.trans.steps.update.Update.processRow(Update.java:315)
        at org.pentaho.di.trans.step.RunThread.run(RunThread.java:40)
        at java.lang.Thread.run(Thread.java:748)

ERROR 11-10 21:31:33,134 - seize_lock_by_name - Errors detected!
ERROR 11-10 21:31:33,134 - seize_lock_by_name - Errors detected!
7

Hi @zvorak,

From the above, it looks as though some DWH processes were already running when you ran kaltura-run-dwh.sh.
Does this query return any results?

mysql> select * from kalturadw_ds.locks where lock_state=1;
8 
mysql&gt; select * from kalturadw_ds.locks where lock_state=1;
Empty set (0.00 sec)

nothing.

on analytics all reports, nothing has been shown.

9

Is there any solution?

My installation has no customization, no appendices, truly plain.
But kaltura analytics NEVER work.
I can’t understand it. why the plain installation would not be good?

10

Hello @zvorak,

What MySQL/MariaDB are you working against? Also, what JRE version is running the DWH/Pentaho code?

Thanks,

11

mysql => mysql-server-5.1.73-8.el6_8.x86_64
java => java-1.8.0-openjdk-1.8.0.191.b12-0.el6_10.x86_64

both of them are automatically installed by kaltura-server relatedly.

12

this is very important implementation.
because of difference on locale, it could happen an error.
I’ve caught some error logs similar like this:

Could not apply the given format dd/MMM/yyyy:HH:mm:ss on the string for 09/Jul/2018:09:56:29 : Format.parseObject(String) failed (script#15)

please apply this patch immediately, I wish.

13

and I’ve figured out DWH lock error, like this:

ERROR 11-10 21:31:33,133 - Seize lock - org.pentaho.di.core.exception.KettleValueException:
LOCKED_STATE Integer : There was a data type error: the data type of java.lang.Boolean object [false] does not correspond to value meta [Integer]

    at org.pentaho.di.core.row.ValueMeta.getString(ValueMeta.java:1358)
    at org.pentaho.di.core.row.RowMeta.getString(RowMeta.java:184)
    at org.pentaho.di.core.row.RowMeta.getString(RowMeta.java:605)
    at org.pentaho.di.trans.steps.update.Update.lookupValues(Update.java:137)
    at org.pentaho.di.trans.steps.update.Update.processRow(Update.java:315)
    at org.pentaho.di.trans.step.RunThread.run(RunThread.java:40)
    at java.lang.Thread.run(Thread.java:748)

ERROR 11-10 21:31:33,134 - seize_lock_by_name - Errors detected!

I’ve already pasted these logs but not emphasized at first time.

at /opt/kaltura/dwh/etlsource/common/seize_lock_by_name.ktr and /opt/kaltura/dwh/etlsource/common/release_lock_by_name.ktr, I’ve changed them like this, and forced to avoid errors.

208 <hop> <from>Register lock</from><to>Get free lock</to><enabled>Y</enabled> </hop> <hop> <from>Get free lock</from><to>Lock is free</to><enabled>Y</enable d> </hop> <hop> <from>Get lock name</from><to>Create lock states</to><enabled>Y</enabled> </hop> <hop> <from>Generate Row</from><to>Get lock name</to><ena bled>Y</enabled> </hop> <hop> <from>Create lock states</from><to>Register lock</to><enabled>Y</enabled> </hop> <hop> <from>Lock is free</from><to>Lock is already seized</to><enabled>Y</enabled> </hop> <hop> <from>Lock is free</from><to>Get Now</to><enabled>Y</enabled> </hop> <!–<hop> <from>Get Now</from><to>Seize lock</to><enabled>Y</enabled> </hop>–> </order>

please check them also. thank you.

14

Hi @zvorak,

It seems as though you simply commented this block in the KTR files:

 <!--<hop> <from>Get Now</from><to>Seize lock</to><enabled>Y</enabled> </hop>-->

While this bypasses the issue because the call will not be made, it is not a solution.

This error confuses me:

Because 09/Jul/2018:09:56:29 seems to correspond with the dd/MMM/yyyy:HH:mm:ss format.

Are you saying the TZ set for PHP via the date.timezone directive, the TZ set at the machine’s level [/etc/localtime, /etc/timezone] and the MySQL TZ do not all match? If so, then they should be aligned. If I have misunderstood you, can you please reiterate and also provide the output for:

$ date
$ php -i |grep date.timezone

and:

mysql> SELECT @@system_time_zone;

Thank you,

15

While this bypasses the issue because the call will not be made, it is not a solution.

yes i know, sorry for annoying you but I’ve thought this error makes consequential processes stopping, and trying to these latter part of batch process.

[root@instance-1 ~]# date
2018年 10月 26日 金曜日 14:19:53 JST
[root@instance-1 ~]# php -i |grep date.timezone
date.timezone => Asia/Tokyo => Asia/Tokyo

and mysql

mysql> SELECT @@system_time_zone;
±-------------------+
| @@system_time_zone |
±-------------------+
| JST |
±-------------------+
1 row in set (0.01 sec)

thank you.

16

Hi, @zvorak, @jess,

Before, our kaltura DWH server generated the following error about “/opt/kaltura/dwh/etlsource/execute/etl_hourly.sh”.

INFO 10-07 04:00:14,634 - Create output files - Finished processing (I=0, O=0, R=1, W=1, U=0, E=0)
INFO 10-07 04:00:14,635 - Mapping input specification - Finished processing (I=0, O=0, R=1, W=1, U=0, E=0)
INFO 10-07 04:00:14,743 - Enrich cycle_id and file_id - play - Finished processing (I=0, O=0, R=1, W=1, U=0, E=0)
INFO 10-07 04:00:14,837 - iterate file - Opening file: /opt/kaltura/dwh/cycles/process/4/cak02bs.cc.yamaguchi-u.ac.jp-kaltura_apache_access_ssl.log-20180710-03
INFO 10-07 04:00:14,841 - parse bandwidth lines - Optimization level set to 9.
INFO 10-07 04:00:14,842 - parse playManifest line - Optimization level set to 9.
INFO 10-07 04:00:14,851 - parse playManifest line - Optimization level set to 9.
INFO 10-07 04:00:14,852 - decode http string - Optimization level set to 9.
INFO 10-07 04:00:14,857 - parse bandwidth lines - Optimization level set to 9.
INFO 10-07 04:00:14,865 - decode http string - Optimization level set to 9.
ERROR 10-07 04:00:19,058 - parse bandwidth lines - Unexpected error
ERROR 10-07 04:00:19,059 - parse bandwidth lines - org.pentaho.di.core.exception.KettleValueException:
Javascript error:
Could not apply the given format dd/MMM/yyyy:HH:mm:ss on the string for 09/Jul/2018:09:56:29 : Format.parseObject(String) failed (script#15)

“09/Jul/2018:09:56:29” seems to correspond with the dd/MMM/yyyy:HH:mm:ss format.

This error message was created when the “etl_hourly.sh” try to process “cak02bs.cc.yamaguchi-u.ac.jp-kaltura_apache_access_ssl.log-20180710-03”.
From the error message, “09/Jul/2018:09:56:29” seems to correspond to “dd/MMM/yyyy:HH:mm:ss” format.
But, However, the format of log-file is as follows.

10.6.209.196 - - [09/Jul/2018:09:56:29 +0900] “POST /api_v3/index.php/service/baseentry/action/list?kalsig=3ec79baff0c8d93e8c4fdfbfa54c734c HTTP/1.1” 200 2266 0/206705 “https://cak02bs.cc.yamaguchi-u.ac.jp/flash/kmc/v5.43.13/kmc.swf” “Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:61.0) Gecko/20100101 Firefox/61.0” “-” 10.6.209.196 “-” “cak02bs.cc.yamaguchi-u.ac.jp” 11737 420355196 + 1334 “-” “-” “-” “-” “no-store, no-cache, must-revalidate, post-check=0, pre-check=0” 101

That is, the actual logs correspond to “dd/MMM/yyyy:HH:mm:ssZ” format.

Since the pentaho uses the java, I created the following java program.

# more TestClass.java
public class TestClass {
  public static void main(String args[]) {
      java.time.LocalDateTime ldt = java.time.LocalDateTime.now();
      System.out.println(java.util.TimeZone.getDefault().getID());
      java.util.TimeZone desiredTimeZone = java.util.TimeZone.getTimeZone(java.util.TimeZone.getDefault().getID());
      java.text.SimpleDateFormat dateFormat = new java.text.SimpleDateFormat("[dd/MMM/yyyy:HH:mm:ssZ]", java.util.Locale.ENGLISH);
      java.time.ZonedDateTime eventTime = ldt.atZone(java.time.ZoneId.of(java.util.TimeZone.getDefault().getID()));
      System.out.println(eventTime);
      System.out.println(eventTime.format(java.time.format.DateTimeFormatter.ofPattern("[dd/MMM/yyyy:HH:mm:ssZ]")));
      eventTime = ldt.atZone(java.time.ZoneId.of("America/New_York"));
      System.out.println(eventTime);
      System.out.println(eventTime.format(java.time.format.DateTimeFormatter.ofPattern("[dd/MMM/yyyy:HH:mm:ssZ]")));
  }
}

The execution result of this program is as follows.

# java TestClass
Asia/Tokyo
2018-10-29T22:47:31.423+09:00[Asia/Tokyo]
29/10/2018:22:47:31+0900
2018-10-29T22:47:31.423-04:00[America/New_York]
29/10/2018:22:47:31-0400

Based on the above results, I have created previously reported patches.
By applying these patches, the errors have been solved.
Now, our DWH server processes log-files normally, and play/view count is updated normally.

However, our patches have a problem.
If the DWH server works under the environment which logs correspond to “dd/MMM/yyyy:HH:mm:ss” format, our patches cause the same errors.
Therefore, it is not appropriate to apply our patches to source code of the Kaltura CE.

Rather, we should consider a mechanism that correctly detects the time format adopted by the server.
Or, we should consider a method that unifies the time format in log-files.
I hope that my report will be helpful for something.

Regards

17

Hi @t-saito,

Thank you very much for your detailed report.

Just to make certain, are you referring to what you’ve included in DWH issue under non-default Timezone configuration?

Thanks again,

18

Hi @jess,

Yes, the “previously reported patches” is referring to

Our patches will work well under certain environments.
But, these pathes don’t work under other environments.

Regards