Converting process never ending & internal error on dashboard

@jess

This is the only error I see in my ‘kaltlog’ at this point.

==> /opt/kaltura/log/kaltura_scripts.log <==
Stack trace:
#0 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(253): KalturaLog::err('Skipping call t...')
--
2016-03-08 18:55:12 [1457299858] [addPermissionsAndItems.php] [addItemToPermissions] ALERT: exception 'Exception' with message 'ERROR - Permission name [] for partner [0] not found in database - skipping!' in /opt/kaltura/app/infra/log/KalturaLog.php:65
Stack trace:
#0 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(284): KalturaLog::alert('ERROR - Permiss...') 

I have also updated the /opt/kaltura/log/kaltura_api_v3.log file found at the link provided with the current log since I re-installed a fresh copy of Kaltura using the most recent repository file and update RPM files.

As I attempted to explain before the issue I am having is KMC console shows that the files are detected then uploaded to system and then in processing. However, even after hours later none of the files every appear as done processing. Nor do any of the files ever appear in the Kaltura admin_console batch report as uploading, processing or completed.

Batch is running and active. The sample videos converted properly and appear in the concole as completed also they show in the batch console as when processing well. None of the media ingested via drop folder is being process to completion.

@jess
Please review my responses and proved some input on resolving this issue. This is the ONLY operational issue left for this specific installation. Since I need to ingest over 1000+ videos using the Drop Floder method I need to get Kaltura to complete the processing of each video after uploading. It is not giving me a failed error it just never moving past “processing” status after three days.

@jess

Do you have any insight on how to fix or troubleshoot this issue yet?

@jess

Here are the errors I found in the “kaltura_api_v3.log” previously provided.

2016-03-08 18:55:14 [0.000172] [107.152.128.122] [665107164] [120] [API] [KalturaFrontController->errorHandler] WARN: /opt/kaltura/app/api_v3/lib/types/KalturaObject.php line 377 - include_once(/opt/kaltura/app/cache//api_v3/fromObject/Map_KalturaUser_kuser.php): failed to open stream: No such file or directory
2016-03-08 18:55:14 [0.000078] [107.152.128.122] [665107164] [121] [API] [KalturaFrontController->errorHandler] WARN: /opt/kaltura/app/api_v3/lib/types/KalturaObject.php line 377 - include_once(): Failed opening '/opt/kaltura/app/cache//api_v3/fromObject/Map_KalturaUser_kuser.php' for inclusion (include_path='/opt/kaltura/app/vendor/htmlpurifier/library:/opt/kaltura/app/vendor/ZendFramework/library:.:/usr/share/pear:/usr/share/php:/opt/kaltura/app:/opt/kaltura/app/vendor/symfony:/opt/kaltura/app/vendor/symfony/vendor:/opt/kaltura/app/vendor/ZendFramework/library:/opt/kaltura/app/alpha:/opt/kaltura/app/alpha/lib:/opt/kaltura/app/alpha/apps/kaltura/lib')

Curently, this is the only errors I see it the log right now. I will re-run the DropFolder process with fewer files to import.

Your permissions of /opt/kaltura/app/cache/ are wrong.
# chown -R kaltura.apache /opt/kaltura/app/cache/
# chmod 775 /opt/kaltura/app/cache/
finally, remove old files with:
# find /opt/kaltura/app/cache/ -type f -exec rm {} ;

@jess

After completing the commands previously mention and following instructions found in this thread

I got rid of most of my errors except the following showing up in ‘kaltlog’ now.

--
2016-03-12 20:14:07 [0.003151] [107.152.128.122] [1684349000] [16] [API] [KalturaEntryService->prepareEntryForInsert] DEBUG: Creating new entry of API type [] core type [] class [entry]
2016-03-12 20:14:07 [0.000855] [107.152.128.122] [1684349000] [17] [API] [KalturaFrontController->getExceptionObject] ERR: exception 'KalturaAPIException' with message 'Conversion profile id "11" not found' in /opt/kaltura/app/api_v3/lib/types/entry/KalturaBaseEntry.php:503
Stack trace:
#0 /opt/kaltura/app/api_v3/lib/types/entry/KalturaBaseEntry.php(481): KalturaBaseEntry->validateConversionProfile(NULL)
--
2016-03-12 20:14:07 [0.000282] [107.152.128.122] [1684349000] [24] [API] [KalturaStatement->execute] DEBUG: Sql took - 0.0001981258392334 seconds
2016-03-12 20:14:07 [0.000165] [107.152.128.122] [1684349000] [25] [API] [KalturaFrontController->getExceptionObject] ERR: exception 'KalturaAPIException' with message 'Entry id "" not found' in /opt/kaltura/app/api_v3/services/BaseEntryService.php:108
Stack trace:
#0 [internal function]: BaseEntryService->addContentAction('', Object(KalturaDropFolderFileResource))
--
2016-03-12 20:14:09 [0.004065] [107.152.128.122] [1215345678] [16] [API] [KalturaEntryService->prepareEntryForInsert] DEBUG: Creating new entry of API type [] core type [] class [entry]
2016-03-12 20:14:09 [0.000892] [107.152.128.122] [1215345678] [17] [API] [KalturaFrontController->getExceptionObject] ERR: exception 'KalturaAPIException' with message 'Conversion profile id "11" not found' in /opt/kaltura/app/api_v3/lib/types/entry/KalturaBaseEntry.php:503
Stack trace:
#0 /opt/kaltura/app/api_v3/lib/types/entry/KalturaBaseEntry.php(481): KalturaBaseEntry->validateConversionProfile(NULL)
--
2016-03-12 20:14:09 [0.000322] [107.152.128.122] [1215345678] [24] [API] [KalturaStatement->execute] DEBUG: Sql took - 0.00022101402282715 seconds
2016-03-12 20:14:09 [0.000168] [107.152.128.122] [1215345678] [25] [API] [KalturaFrontController->getExceptionObject] ERR: exception 'KalturaAPIException' with message 'Entry id "" not found' in /opt/kaltura/app/api_v3/services/BaseEntryService.php:108
Stack trace:
#0 [internal function]: BaseEntryService->addContentAction('',     Object(KalturaDropFolderFileResource))  
--
2016-03-12 20:15:48 [0.000271] [66.249.66.43] [717365057] [15] [PS2] [KalturaStatement->execute] DEBUG: Sql took - 0.00018787384033203 seconds
2016-03-12 20:15:48 [0.000188] [66.249.66.43] [717365057] [16] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 22 - requested ui_conf not found' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
--
2016-03-12 20:15:48 [0.000266] [66.249.66.40] [1250217625] [15] [PS2] [KalturaStatement->execute] DEBUG: Sql took - 0.00018501281738281 seconds
2016-03-12 20:15:48 [0.000191] [66.249.66.40] [1250217625] [16] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 22 - requested ui_conf not found' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')

I am finding a lot of items not found. Regardless of which Coversion profile I select in the configuration menu I get the same error that it is not found.

@jess

I have completed the update to the latest version on one of my systems and I am still getting an error in my ‘kaltlog’ saying that my conversion profile is not found or missing. Please advise how I am to resolve this issue?

--
2016-03-15 12:33:37 [0.004787] [107.152.128.122] [1459366536] [16] [API] [KalturaEntryService->prepareEntryForInsert] DEBUG: Creating new entry of API type [] core type [] class [entry]
2016-03-15 12:33:37 [0.000945] [107.152.128.122] [1459366536] [17] [API] [KalturaFrontController->getExceptionObject] ERR: exception 'KalturaAPIException' with message 'Conversion profile id "11" not found' in /opt/kaltura/app/api_v3/lib/types/entry/KalturaBaseEntry.php:503
Stack trace:
#0 /opt/kaltura/app/api_v3/lib/types/entry/KalturaBaseEntry.php(481): KalturaBaseEntry->validateConversionProfile(NULL)
--
2016-03-15 12:33:37 [0.000265] [107.152.128.122] [1459366536] [24] [API] [KalturaStatement->execute] DEBUG: Sql took - 0.00018095970153809 seconds
2016-03-15 12:33:37 [0.000153] [107.152.128.122] [1459366536] [25] [API] [KalturaFrontController->getExceptionObject] ERR: exception 'KalturaAPIException' with message 'Entry id "" not found' in /opt/kaltura/app/api_v3/services/BaseEntryService.php:108
Stack trace:
#0 [internal function]: BaseEntryService->addContentAction('', Object(KalturaDropFolderFileResource))

@hiphopservers,

Something is wrong with your DB deployment. This is shown by many of the logs you posted.
I honestly think the best thing to do is to drop the DB and repopulate it.

Follow https://github.com/kaltura/platform-install-packages/blob/Kajam-11.11.0/doc/kaltura-packages-faq.md#fresh-database-installation on how to do that.

If, when redeploying, you come across issues, report them with the exact logs and I’ll help you.

Correctly a bad DB deployment by hand is very complex and hardly worth the time.

Thank you,

@jess

I completed the reconfiguration. Here is what I came accross in the various logs

Populating DB with data.. please wait..
Output for /opt/kaltura/app/deployment/base/scripts/installPlugins.php being logged into /opt/kaltura/log/installPlugins.log
Output for /opt/kaltura/app/deployment/base/scripts/insertDefaults.php being logged into /opt/kaltura/log/insertDefaults.log
Output for /opt/kaltura/app/deployment/base/scripts/insertPermissions.php being logged into /opt/kaltura/log/insertPermissions.log
Output for /opt/kaltura/app/deployment/base/scripts/insertContent.php being logged into /opt/kaltura/log/insertContent.log

Nothing appears in the first two logs.

installPlugins.log
insertDefaults.log

I found the following errors in the ‘insertPermissions’ log.

2016-03-15 14:18:59 [KalturaStatement->execute] DEBUG: /* tig03.hiphopservers.com[928451227][propel] */ SELECT permission.ID, permission.TYPE, permission.NAME, permission.FRIENDLY_NAME, permission.DESCRIPTION, permission.PARTNER_ID, permission.STATUS, permission.DEPENDS_ON_PERMISSION_NAMES, permission.TAGS, permission.CREATED_AT, permission.UPDATED_AT, permission.CUSTOM_DATA FROM `permission` WHERE permission.NAME='PARTNER_-1_GROUP_*_PERMISSION' AND permission.TYPE IN ('1','4') AND permission.PARTNER_ID IN ('0','0','-1') AND permission.STATUS<>'3' LIMIT 1
2016-03-15 14:18:59 [KalturaStatement->execute] DEBUG: Sql took - 0.00021791458129883 seconds
2016-03-15 14:18:59 [addItemToPermissions] ALERT: exception 'Exception' with message 'ERROR - Permission name [PARTNER_-1_GROUP_*_PERMISSION] for partner [0] not found in database - skipping!' in /opt/kaltura/app/infra/log/KalturaLog.php:65
Stack trace:
#0 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(284): KalturaLog::alert('ERROR - Permiss...')
#1 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(197): addItemToPermissions(Object(kApiActionPermissionItem), Array, '0')
#2 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(40): addActionPermissionItem(Object(Zend_Config))
#3 {main}
2016-03-15 14:18:59 [KalturaStatement->execute] DEBUG: /* tig03.hiphopservers.com[928451227][propel] */ SELECT permission_item.ID, permission_item.TYPE, permission_item.PARTNER_ID, permission_item.PARAM_1, permission_item.PARAM_2, permission_item.PARAM_3, permission_item.PARAM_4, permission_item.PARAM_5, permission_item.TAGS, permission_item.CREATED_AT, permission_item.UPDATED_AT, permission_item.CUSTOM_DATA FROM `permission_item` WHERE permission_item.PARAM_1='groupuser' AND permission_item.PARAM_2='delete' AND permission_item.PARTNER_ID IN ('0','0') AND permission_item.TYPE='kApiActionPermissionItem' LIMIT 1

2016-03-15 14:18:59 [KalturaStatement->execute] DEBUG: Sql took - 0.00014710426330566 seconds
2016-03-15 14:18:59 [addItemToPermissions] ALERT: exception 'Exception' with message 'ERROR - Permission name [PARTNER_-1_GROUP_*_PERMISSION] for partner [0] not found in database - skipping!' in /opt/kaltura/app/infra/log/KalturaLog.php:65
Stack trace:
#0 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(284): KalturaLog::alert('ERROR - Permiss...')
#1 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(197): addItemToPermissions(Object(kApiActionPermissionItem), Array, '0')
#2 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(40): addActionPermissionItem(Object(Zend_Config))
#3 {main}

2016-03-15 14:18:59 [KalturaStatement->execute] DEBUG: Sql took - 0.00021481513977051 seconds
2016-03-15 14:18:59 [addItemToPermissions] ALERT: exception 'Exception' with message 'ERROR - Permission name [PARTNER_-1_GROUP_*_PERMISSION] for partner [0] not found in database - skipping!' in /opt/kaltura/app/infra/log/KalturaLog.php:65
Stack trace:
#0 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(284): KalturaLog::alert('ERROR - Permiss...')
#1 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(197): addItemToPermissions(Object(kApiActionPermissionItem), Array, '0')
#2 /opt/kaltura/app/alpha/scripts/utils/permissions/addPermissionsAndItems.php(40): addActionPermissionItem(Object(Zend_Config))
#3 {main}

2016-03-15 14:19:45 [KalturaStatement->execute] DEBUG: /* tig03.hiphopservers.com[1783304601][propel] */ SELECT permission_item.ID, permission_item.TYPE, permission_item.PARTNER_ID, permission_item.PARAM_1, permission_item.PARAM_2, permission_item.PARAM_3, permission_item.PARAM_4, permission_item.PARAM_5, permission_item.TAGS, permission_item.CREATED_AT, permission_item.UPDATED_AT, permission_item.CUSTOM_DATA FROM `permission_item` WHERE permission_item.PARAM_1='stats' AND permission_item.PARAM_2='reportkceerror' AND permission_item.PARTNER_ID IN ('0','0') AND permission_item.TYPE='kApiActionPermissionItem' LIMIT 1
2016-03-15 14:19:45 [KalturaStatement->execute] DEBUG: Sql took - 0.00048184394836426 seconds
2016-03-15 14:19:45 [KalturaStatement->execute] DEBUG: /* tig03.hiphopservers.com[1783304601][propel] */ INSERT INTO permission_item (`ID`,`TYPE`,`PARTNER_ID`,`PARAM_1`,`PARAM_2`,`PARAM_3`,`PARAM_4`,`PARAM_5`,`TAGS`,`CREATED_AT`,`UPDATED_AT`) VALUES (NULL,'kApiActionPermissionItem','0','stats','reportkceerror','','','','','2016-03-15 14:19:45','2016-03-15 14:19:45')
2016-03-15 14:19:45 [KalturaStatement->execute] DEBUG: Sql took - 0.022797107696533 seconds
2016-03-15 14:19:45 [kObjectCreatedEvent->__construct] DEBUG: Event [kObjectCreatedEvent] object type [kApiActionPermissionItem] id [271]
2016-03-15 14:19:45 [kObjectSavedEvent->__construct] DEBUG: Event [kObjectSavedEvent] object type [kApiActionPermissionItem] id [271]
2016-03-15 14:19:45 [addActionPermissionItem] NOTICE: New permission item id [271] added for [stats->reportkceerror] partner id [0]

Everything after that seems to repeat the same errors over and over. I will submit the result of the DWH logs in my other thread related to analytic reporting issues.

Let me note that my installation is configured as an SSL installation. I have done two other installation with non-SSL and oddly even with the various issues. When I run the config all script it actually runs completely though without errors assuming everything is in order. The SSL enable configuration never runs completely without breaking at the same part.

This then requires me to fix the issue in the non httpd zzzkaltura.conf file then manually re-run the last two steps of the script. My guess is that this is part of the issue with the configuration never actually completing fully. If I am missing some of the steps after the break point then this could be the point where things go array.

    Generating UI confs..
    Shutting down monit:                                       [FAILED]
    Starting monit: Starting Monit 5.13 daemon with http interface at [*]:2812
                                                               [  OK  ]
    Running Batch config...


    kaltura-batch-11.10.0-2.noarch
    base-config completed successfully, if you ever want to re-configure your system (e.g. change DB hostname) run the following script:
    # rm /opt/kaltura/app/base-config.lock
    # /opt/kaltura/bin/kaltura-base-config.sh


    Reloading httpd: not reloading due to configuration syntax error
                                                               [FAILED]


    kaltura-batch-config.sh FAILED with: 18597 on line 98

    Archving logs to /opt/kaltura/log/log_15_03_16_19_37.tar.gz...
    ERROR: /opt/kaltura/bin/kaltura-batch-config.sh failed:( You can re-run it when the issue is fixed.

The issue causing the break here is the script does not correctly insert the proper token values for the HTTP port and paths to the log files. So HTTPD can not properly restart. I would request that this be fixed to work properly during SSL installation on RPM setups in the next release. It would make for a smoother install avoiding breaking the system installation.

@jess

I figured out what the missing or unable to find transcoding profile comes from. By default there is only one Transcoding profile for each publisher and that is the default which is profile number 6. However, when setting up a drop folder you get multiple option to choose from depending on what you have setup in your configuration for that publisher. None, of them work except the default because none of them existing in the Publishers transcoding profile list except the Default (6).

Hence the error I was getting because profiles number 11 and 14 do not existing for any users including administrator. I am not sure why they even appear in the list not why passthrough which is number 11 is the default if the default (6) is the only one that works.

Now, that Kaltura is ingesting the videos and attempting to encode them my next problem is after Kaltura connects to my host and captures a list of files to ingest ‘kaltlog’ spits the following error.

--
2016-03-15 21:55:16 [0.000668] [1750917290] [22] [BATCH] [KCurlWrapper->setSourceUrlAndprotocol] INFO: Setting source URL to [ftp://ftpuser@bbwcamhouse.com:passcode@bbwcamhouse.com/vod_import/1057.mp4]
2016-03-15 21:55:16 [0.048919] [1750917290] [23] [BATCH] [KJobHandlerWorker->closeJob] ERR: exception 'Exception' with message 'Couldn't read file. Error: Couldn't resolve host 'bbwcamhouse.com:passocde@bbwcamhouse.com'' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/batch/batches/KJobHandlerWorker.class.php(372): KalturaLog::err('Couldn't read f...')

The second pass to connect is not using proper syntax to connect to the FTP host again. Neither by browser or FTP client. An it should not be trying to connect using a web accessable directory because there isn’t one. Hence the reason for connect via FTP. I have no clue why it is passing the connection information in this way.

Please provide the output of:
mysql> select * from drop_folder\G

While masking your user, passwd and actual host of course and I’ll take a look.

Return the following information:

*************************** 1. row ***************************
id: 1
partner_id: 99
name: VOD
description: Test
type: 2
status: 1
dc: 0
path: /vod_import
conversion_profile_id: 6
file_delete_policy: 3
file_handler_type: 1
file_name_patterns: *
file_handler_config: O:34:“DropFolderContentFileHandlerConfig”:3:{s:54:" DropFolderContentFileHandlerConfig contentMatchPolicy";i:1;s:45:" DropFolderContentFileHandlerConfig slugRegex";s:30:"/(?P.+)[.]\w{2,}/";s:14:" * handlerType";i:1;}
tags: bbwch
error_code: NULL
error_description: NULL
created_at: 2016-03-15 21:47:07
updated_at: 2016-03-16 12:16:01
custom_data: a:14:{s:24:“file_size_check_interval”;i:30;s:21:“auto_file_delete_days”;i:0;s:25:“ignore_file_name_patterns”;s:0:"";s:11:“incremental”;b:1;s:19:“metadata_profile_id”;i:0;s:30:“categories_metadata_field_name”;s:0:"";s:19:“enforce_entitlement”;b:0;s:18:“should_validate_ks”;b:0;s:8:“ftp_host”;s:15:“mydomain.com";s:8:“ftp_port”;i:21;s:12:“ftp_username”;s:20:"ftpuser@mydomain.com”;s:12:“ftp_password”;s:9:“the-passowrd”;s:16:“last_accessed_at”;i:1458144961;s:19:“last_file_timestamp”;i:1458092760;}
1 row in set (0.00 sec)

The information here and what was display at the time of the error are different. As I mention part of the information in the second pass to connect was cut off in review of the error log.

Hi @hiphopservers,

Not quite sure I understand. The output you pasted indicates you do not at the moment have any drop folders configured.
Did you delete the one you configured? If so, create it again and send me the DB record which was created. Unless you don’t want to use a dropfolder at all in which case, what are the areas in which you currently have issues with?

Hello @jess

I am not sure I follow your response the same information in that record pasted is contains the information I configure in the Admin Console for that user.

I am not sure what you mean when you say it my record show I don’t have it configured. What am I missing to complete the configuration. This profile is connecting and attempting to download and import any media I add tot the folder. My issue is the attempts fail and the media is never imported.

@hiphopservers,

This is wrong. Partner 99 is a template partner which should only be used to edit things you wish other partners to inherit. For example, sample content. You should go to admin console->publishers and create your own partner and do all your configurations on it.

Once you have, if it does not work, provide the record as seen by the query I sent you.

Thanks,

@jess

After following your instructions and setting up a new publisher I am not getting cannot connect to host error anymore but I am still getting errors as show here from ‘kaltlog’.

--
2016-03-16 19:38:52 [0.000095] [24.49.36.237] [962681318] [56] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-16 19:38:52 [0.000244] [24.49.36.237] [962681318] [57] [PS2] [kCoreException->__construct] ERR: exception 'kFileSyncException' with message 'no ready filesync on current DC' in /opt/kaltura/app/alpha/apps/kaltura/lib/myEntryUtils.class.php:783
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3348): myEntryUtils::resizeEntryImage(Object(entry), 0, 120, 90, 2, 'F7F7F7', NULL, 0, 0, 0, 0, 0, -1, '-1', '-1')
--
2016-03-16 19:38:52 [0.000091] [24.49.36.237] [962681318] [65] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-16 19:38:52 [0.000105] [24.49.36.237] [962681318] [66] [PS2] [entry->getLocalThumbFilePath] ERR: exception 'Exception' with message 'No ready fileSync found on any DC.' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3365): KalturaLog::err('No ready fileSy...')
--
#16 {main}
2016-03-16 19:38:52 [0.000113] [24.49.36.237] [962681318] [67] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 10 - missing thumbnail fileSync for entry' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
188311.mp4--
2016-03-16 19:39:52 [0.000250] [107.152.128.122] [1507144381] [30] [API] [KalturaStatement->execute] DEBUG: Sql took - 0.00016093254089355 seconds
2016-03-16 19:39:52 [0.000373] [107.152.128.122] [1507144381] [31] [API] [kDropFolderEventsConsumer->setFileError] ERR: exception 'Exception' with message 'Error with file [3] -Failed in file transferring from the drop folder to Kaltura' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/plugins/drop_folder/lib/kDropFolderEventsConsumer.php(439): KalturaLog::err('Error with file...') 

Now, the system is not make a thumbnail nor is it completing the file transfer to load the video in the system from the drop folder.

I did a sanity check after searching the forums for someone with the same errors and got these errors during the sanity check.

[kaltura_logo_animated_blue.flv - 0_n4d29qt2 status] [PASSED, RC: 0] - [81.971000760]
[Create thumb for 0_n4d29qt2] [PASSED, RC: 0] - [.506050967]
[Clipping 0_n4d29qt2] [PASSED, RC: 0] - [1.616080449]
PHP Fatal error:  Uncaught exception 'KalturaException' with message 'The original flavor asset is missing' in /opt/kaltura/web/content/clientlibs/php5/KalturaClientBase.php:894
Stack trace:
#0 /opt/kaltura/web/content/clientlibs/php5/KalturaClient.php(4364): KalturaClientBase->throwExceptionIfError(Array)
#1 /opt/kaltura/bin/clip_test.php(46): KalturaMediaService->addContent('0_g19rgm6z', Object(KalturaOperationResource))
#2 /opt/kaltura/bin/clip_test.php(62): clipi(Object(KalturaClient), '0_n4d29qt2', '1')
#3 {main}
  thrown in /opt/kaltura/web/content/clientlibs/php5/KalturaClientBase.php on line 894
[Trimming 0_n4d29qt2] [FAILED, RC: 255] - [.512916821]
[Mock playback 0_n4d29qt2] [PASSED, RC: 0] - [.574949924]
[Adding captions to 0_n4d29qt2] [PASSED, RC: 0] - [.772788605]
[Searching for Example||Deja||Bold in 0_n4d29qt2 metadata] [PASSED, RC: 0] - [.389895386]
PHP Fatal error:  Uncaught exception 'KalturaException' with message 'The original flavor asset is missing' in /opt/kaltura/web/content/clientlibs/php5/KalturaClientBase.php:894
Stack trace:
#0 /opt/kaltura/web/content/clientlibs/php5/KalturaClient.php(4525): KalturaClientBase->throwExceptionIfError(Array)
#1 /opt/kaltura/bin/recon.php(20): KalturaMediaService->convert('0_n4d29qt2', NULL, NULL)
#2 {main}
  thrown in /opt/kaltura/web/content/clientlibs/php5/KalturaClientBase.php on line 894
[Calling media->convert on 0_n4d29qt2 failed] [FAILED, RC: 255] - [.243771678]
Napping 30 seconds to allow mail to be sent out..
[Found an email sending entry for mb-tig03.hiphopservers.com@kaltura.com[PID is 101] in /var/log/maillog] [PASSED, RC: 0] - [30.134165439]
Testing analytics, be patient..

Please note: if you are running this test on a clustered ENV, it will fail but this does not mean there is an actual problem.
The tech information as to why is available here:
https://github.com/kaltura/platform-install-packages/issues/106#issuecomment-42837404

[DWH cycle] [FAILED, RC: 255] - [34.014480941]

Hi @hiphopservers,

To start off, I’m not sure I understand whether or not entry ID 0_n4d29qt2 was successfully transcoded or not. What is the entry status?
mysql> select id,name,status from entry where id=‘0_n4d29qt2’;

Also, “The original flavor asset is missing”, find this string in /opt/kaltura/log/kaltura_api_v3.log and look at the queries done before that and leading to this message.

Would probably be easier for you if you first clear the log with:

\# :> /opt/kaltura/log/kaltura_api_v3.log

Also, do files you uploaded with the new partner you created become ready or not?

Once we get to a situation when manual uploads transcode, the entry becomes ready and is playable, we can talk about the dropfolder, did you create it under a new partner and tried that?

Hello @jess

The status is download failed. At this point it the process is as follows:

  1. Uploading
  2. Processing
  3. Downloading
  4. Downloading Failed

The information previously posted was in ‘kaltlog’ after I tried to ingest two media files one small and the second a large file. Now, if I take say a 6 mb via and manually upload it form the the new publisher KMC I created iit processes and transcodes the file without an issue and the file status eventually becomes ‘ready’. After it is ready there is no playback issue. This is one of the same sample files I am trying to ingest via the drop folder.

At this point I have cleared the logs for this installation dropped all databases and rerun the installation from scratch. and I will track the errors with ‘kaltlog’ to a file while I go through each process. Then open the individutal logs to find errors.

What was the grep command to scan each individual log for errors related to this issue? I will paste the results minus any passwords and private information.

Hi @hiphopservers

Use:
# kaltlog
kaltlog is aliased to `tail -f /opt/kaltura/log/.log /opt/kaltura/log/batch/.log | grep -A 1 -B 1 --color “ERR:|PHP|trace|CRIT|[error]”’

Then drill down in each log as we agreed.

@jess

Oddly, I reinstalled the host and got all the same errors on both types of uploads to the host from KMC uploading and drop folder attempts. I got frustrated and took a break. Cleared all the logs to have a fresh strart this morning and make this post with all the available information. However, now I upload via KMC directly to Kaltura and the video completely processes and becomes ready. It did return the following errors duing the conversion process before becoming ready in KMC console.

            [tmp_name] => /opt/kaltura/web/tmp/phphF66lw
            [error] => 0
            [size] => 52885634
--
            [tmp_name] => /opt/kaltura/web/tmp/phphF66lw
            [error] => 0
            [size] => 52885634
--
2016-03-19 09:41:07 [0.000295] [107.152.128.122] [1579117781] [717] [API] [KalturaStatement->execute] DEBUG: Sql took - 0.00019598007202148 seconds
2016-03-19 09:41:07 [0.000233] [107.152.128.122] [1579117781] [718] [API] [kBatchManager::createFlavorAsset] ERR: exception 'Exception' with message 'Flavor [7] is none-comply' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/batch2/kBatchManager.php(88): KalturaLog::err('Flavor [7] is n...')

Now, when I attempt to upload to the same file via drop folder the process stopped at downloading, which from the errors looked like the start of conversion. It return the following errors.

2016-03-19 09:48:56 [0.000096] [24.49.36.237] [1529757653] [56] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 09:48:56 [0.000281] [24.49.36.237] [1529757653] [57] [PS2] [kCoreException->__construct] ERR: exception 'kFileSyncException' with message 'no ready filesync on current DC' in /opt/kaltura/app/alpha/apps/kaltura/lib/myEntryUtils.class.php:783
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3348): myEntryUtils::resizeEntryImage(Object(entry), 0, 120, 90, 2, 'F7F7F7', NULL, 0, 0, 0, 0, 0, -1, '-1', '-1')
--
2016-03-19 09:48:56 [0.000087] [24.49.36.237] [1529757653] [65] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 09:48:56 [0.000114] [24.49.36.237] [1529757653] [66] [PS2] [entry->getLocalThumbFilePath] ERR: exception 'Exception' with message 'No ready fileSync found on any DC.' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3365): KalturaLog::err('No ready fileSy...')
--
#16 {main}
2016-03-19 09:48:56 [0.000119] [24.49.36.237] [1529757653] [67] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 10 - missing thumbnail fileSync for entry' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
--
2016-03-19 09:50:21 [0.000091] [24.49.36.237] [1369558539] [56] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 09:50:21 [0.000232] [24.49.36.237] [1369558539] [57] [PS2] [kCoreException->__construct] ERR: exception 'kFileSyncException' with message 'no ready filesync on current DC' in /opt/kaltura/app/alpha/apps/kaltura/lib/myEntryUtils.class.php:783
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3348): myEntryUtils::resizeEntryImage(Object(entry), 0, 120, 90, 2, 'F7F7F7', NULL, 0, 0, 0, 0, 0, -1, '-1', '-1')
--
2016-03-19 09:50:21 [0.000090] [24.49.36.237] [1369558539] [65] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 09:50:21 [0.000109] [24.49.36.237] [1369558539] [66] [PS2] [entry->getLocalThumbFilePath] ERR: exception 'Exception' with message 'No ready fileSync found on any DC.' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3365): KalturaLog::err('No ready fileSy...')
--
#16 {main}
2016-03-19 09:50:21 [0.000127] [24.49.36.237] [1369558539] [67] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 10 - missing thumbnail fileSync for entry' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
2016-03-19 09:48:56 [0.000096] [24.49.36.237] [1529757653] [56] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 09:48:56 [0.000281] [24.49.36.237] [1529757653] [57] [PS2] [kCoreException->__construct] ERR: exception 'kFileSyncException' with message 'no ready filesync on current DC' in /opt/kaltura/app/alpha/apps/kaltura/lib/myEntryUtils.class.php:783
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3348): myEntryUtils::resizeEntryImage(Object(entry), 0, 120, 90, 2, 'F7F7F7', NULL, 0, 0, 0, 0, 0, -1, '-1', '-1')
--
2016-03-19 09:48:56 [0.000087] [24.49.36.237] [1529757653] [65] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 09:48:56 [0.000114] [24.49.36.237] [1529757653] [66] [PS2] [entry->getLocalThumbFilePath] ERR: exception 'Exception' with message 'No ready fileSync found on any DC.' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3365): KalturaLog::err('No ready fileSy...')
--
#16 {main}
2016-03-19 09:48:56 [0.000119] [24.49.36.237] [1529757653] [67] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 10 - missing thumbnail fileSync for entry' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
--
2016-03-19 09:50:21 [0.000091] [24.49.36.237] [1369558539] [56] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 09:50:21 [0.000232] [24.49.36.237] [1369558539] [57] [PS2] [kCoreException->__construct] ERR: exception 'kFileSyncException' with message 'no ready filesync on current DC' in /opt/kaltura/app/alpha/apps/kaltura/lib/myEntryUtils.class.php:783
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3348): myEntryUtils::resizeEntryImage(Object(entry), 0, 120, 90, 2, 'F7F7F7', NULL, 0, 0, 0, 0, 0, -1, '-1', '-1')
--
2016-03-19 09:50:21 [0.000090] [24.49.36.237] [1369558539] [65] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 09:50:21 [0.000109] [24.49.36.237] [1369558539] [66] [PS2] [entry->getLocalThumbFilePath] ERR: exception 'Exception' with message 'No ready fileSync found on any DC.' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3365): KalturaLog::err('No ready fileSy...')
--
#16 {main}
2016-03-19 09:50:21 [0.000127] [24.49.36.237] [1369558539] [67] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 10 - missing thumbnail fileSync for entry' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
--
2016-03-19 09:53:54 [0.000223] [107.152.128.122] [1981576908] [30] [API] [KalturaStatement->execute] DEBUG: Sql took - 0.00013184547424316 seconds
2016-03-19 09:53:54 [0.005828] [107.152.128.122] [1981576908] [31] [API] [kDropFolderEventsConsumer->setFileError] ERR: exception 'Exception' with message 'Error with file [2] -Failed in file transferring from the drop folder to Kaltura' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/plugins/drop_folder/lib/kDropFolderEventsConsumer.php(439): KalturaLog::err('Error with file...')

The first question is do I have drop folder’s conversion profile setup properly. I selected the defautl one but there is a passthrough option but last time I tried that it didn’t work So with that said ‘Desktop’ uploading works with minimal errors but drop folder is still not working.

Here are the results of the SQL query you asked for as well.

mysql> select id,name,status from entry where id='0_js3qfo2i';
+------------+------+--------+
| id         | name | status |
+------------+------+--------+
| 0_js3qfo2i | 1057 |     -2 |
+------------+------+--------+
1 row in set (0.00 sec)

This is the SQL results for the media uploaded via deskop.

mysql> select id,name,status from entry where id='0_mxryf83v';
+------------+------+--------+
| id         | name | status |
+------------+------+--------+
| 0_mxryf83v | 1057 |      2 |
+------------+------+--------+
1 row in set (0.00 sec)

I did try a second time and created a new transcoding profile with only source slected and I got similar results.

--
2016-03-19 10:21:38 [0.133537] [337943751] [33] [BATCH] [KAsyncImport->fetchFile] DEBUG: Curl results:
2016-03-19 10:21:38 [0.000455] [337943751] [34] [BATCH] [KJobHandlerWorker->closeJob] ERR: exception 'Exception' with message 'Error: Couldn't resolve host 'my-domain.com:ftp-passwd@my-domain.com'' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/batch/batches/KJobHandlerWorker.class.php(372): KalturaLog::err('Error: Couldn't...')
--
2016-03-19 10:22:01 [0.000092] [24.49.36.237] [682046333] [56] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 10:22:01 [0.000238] [24.49.36.237] [682046333] [57] [PS2] [kCoreException->__construct] ERR: exception 'kFileSyncException' with message 'no ready filesync on current DC' in /opt/kaltura/app/alpha/apps/kaltura/lib/myEntryUtils.class.php:783
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3348): myEntryUtils::resizeEntryImage(Object(entry), 0, 120, 90, 2, 'F7F7F7', NULL, 0, 0, 0, 0, 0, -1, '-1', '-1')
--
2016-03-19 10:22:01 [0.000087] [24.49.36.237] [682046333] [65] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 10:22:01 [0.000109] [24.49.36.237] [682046333] [66] [PS2] [entry->getLocalThumbFilePath] ERR: exception 'Exception' with message 'No ready fileSync found on any DC.' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3365): KalturaLog::err('No ready fileSy...')
--
#16 {main}
2016-03-19 10:22:01 [0.000117] [24.49.36.237] [682046333] [67] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 10 - missing thumbnail fileSync for entry' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
--
2016-03-19 10:22:52 [0.000091] [24.49.36.237] [1028756867] [56] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 10:22:52 [0.000361] [24.49.36.237] [1028756867] [57] [PS2] [kCoreException->__construct] ERR: exception 'kFileSyncException' with message 'no ready filesync on current DC' in /opt/kaltura/app/alpha/apps/kaltura/lib/myEntryUtils.class.php:783
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3348): myEntryUtils::resizeEntryImage(Object(entry), 0, 340, 194, 1, 'ffffff', NULL, 0, 0, 0, 0, 0, -1, '-1', '-1')
--
2016-03-19 10:22:52 [0.000089] [24.49.36.237] [1028756867] [65] [PS2] [kFileSyncUtils::getReadyFileSyncForKey] NOTICE: FileSync was not found
2016-03-19 10:22:52 [0.000112] [24.49.36.237] [1028756867] [66] [PS2] [entry->getLocalThumbFilePath] ERR: exception 'Exception' with message 'No ready fileSync found on any DC.' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/lib/model/entry.php(3365): KalturaLog::err('No ready fileSy...')
--
#16 {main}
2016-03-19 10:22:52 [0.000132] [24.49.36.237] [1028756867] [67] [PS2] [KExternalErrors::dieError] ERR: exception 'Exception' with message 'exiting on error 10 - missing thumbnail fileSync for entry' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/alpha/apps/kaltura/lib/KExternalErrors.class.php(128): KalturaLog::err('exiting on erro...')
--
2016-03-19 10:26:41 [0.000650] [1911012826] [22] [BATCH] [KCurlWrapper->setSourceUrlAndprotocol] INFO: Setting source URL to [ftp://ftp-user@my-domain.com:ftp-passwd@mydomain.com/vod_import/1057.mp4]
2016-03-19 10:26:41 [0.080334] [1911012826] [23] [BATCH] [KJobHandlerWorker->closeJob] ERR: exception 'Exception' with message 'Couldn't read file. Error: Couldn't resolve host 'my-domain.com:ftp-passwd@my-domain.com'' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/batch/batches/KJobHandlerWorker.class.php(372): KalturaLog::err('Couldn't read f...')
--
2016-03-19 10:26:41 [0.000211] [107.152.128.122] [1689877907] [30] [API] [KalturaStatement->execute] DEBUG: Sql took - 0.00012493133544922 seconds
2016-03-19 10:26:41 [0.000361] [107.152.128.122] [1689877907] [31] [API] [kDropFolderEventsConsumer->setFileError] ERR: exception 'Exception' with message 'Error with file [5] -Failed in file transferring from the drop folder to Kaltura' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/plugins/drop_folder/lib/kDropFolderEventsConsumer.php(439): KalturaLog::err('Error with file...')

So this scenario look like it had issue with making thumbnail again and then was ready to publish but could not connect to FTP a second time to move the source file. Guess I will remove source file from all transcoding profiles til that is fixed.

Specifically, this needs to be fixed in the actual source code to pass the connect information in full like the first pass.

DEBUG: Curl results:
    2016-03-19 10:21:38 [0.000455] [337943751] [34] [BATCH] [KJobHandlerWorker->closeJob] ERR: exception 'Exception' with message 'Error: Couldn't resolve host 'my-domain.com:ftp-passwd@my-domain.com'' in /opt/kaltura/app/infra/log/KalturaLog.php:83
    Stack trace:

Here the source URL is set but the full variable is not used to connect.

2016-03-19 10:26:41 [0.000650] [1911012826] [22] [BATCH] [KCurlWrapper->setSourceUrlAndprotocol] INFO: Setting source URL to [ftp://ftp-user@my-domain.com:ftp-passwd@mydomain.com/vod_import/1057.mp4]
2016-03-19 10:26:41 [0.080334] [1911012826] [23] [BATCH] [KJobHandlerWorker->closeJob] ERR: exception 'Exception' with message 'Couldn't read file. Error: Couldn't resolve host 'my-domain.com:ftp-passwd@my-domain.com'' in /opt/kaltura/app/infra/log/KalturaLog.php:83
Stack trace:
#0 /opt/kaltura/app/batch/batches/KJobHandlerWorker.class.php(372): KalturaLog::err('Couldn't read f...')