KMC User gets no e-mail notification when he attempts to download video

mpowell · October 29, 2019, 5:23pm

In the KMC, the user goes to the content tab, places a check mark beside a video, then at the bottom right under “Bulk Actions”, he selects “Download”. A pop-up comes up, he clicks “Submit”, then gets a window that says “Your download request is being processed. A download link will be sent to user@domain.com once processing is completed”. The link is never sent through e-mail. As far as I know, every user who has tried this has the same experience.

I have looked at /var/log/maillog and the only messages that are ever sent are from root to root. Postfix is configured to smart-host to smtp-relay-internal.domain.com, which is as it should be.

I don’t see any way to configure the SMTP server in either the Admin portal or in the KMC.

I looked at the config files at /opt/kaltura/app/configurations and didn’t see anything about SMTP configuration.

How can the server be configured to send the download links to users?

Thanks,
Mark

jess · November 4, 2019, 9:46am

Hello @mpowell,

This particular message is sent using the same mechanism all other messages are sent by: the batch daemon. You do not need to configure the SMTP host and credentials at the application level. If you have a running MTA on TCP 25, it should work correctly. A few questions:
0. Are you getting other system notifications (partner/user creation for example)?

If not, do you receive a message when you use PHP’s mail() function from a test snippet like so:

<?php
mail($to, $subject,$message);

If that doesn’t work either, I suggest you check the value you have for the sendmail_path PHP directive, maybe it’s incorrectly set.
If you are receiving other notifications but not this one, what version of CE are you running? I’d start by checking the /opt/kaltura/log/batch/bulkdownloadcloser*.log as well as the main batch log /opt/kaltura/log/kaltura_batch.log where you should see something along the lines of:

[BATCH] [KProcessWrapper->init] DEBUG: Now executing [setsid /usr/bin/php /opt/kaltura/app/batch/batches/BulkDownload/KAsyncBulkDownloadCloserExe.php
..

We can continue troubleshooting based on your findings,

Cheers,

mpowell · November 13, 2019, 2:27pm

Hi jess,
Thanks for you reply and for your help. See the code block below regarding the things I’ve tried.

Postfix is listening.

[root@KALTURA2 postfix]# netstat -tlpn | grep 25
tcp        0      0 127.0.0.1:25                0.0.0.0:*                   LISTEN      13710/master
tcp        0      0 ::1:25                      :::*                        LISTEN      13710/master

The mail() function was using localhost, and I changed it to smtp-relay-internal.

[mail function]
; For Win32 only.
; http://www.php.net/manual/en/mail.configuration.php#ini.smtp
SMTP = localhost
; http://www.php.net/manual/en/mail.configuration.php#ini.smtp-port
smtp_port = 25
[root@KALTURA2 postfix]# grep SMTP /etc/php.ini
;SMTP = localhost
SMTP = smtp-relay-internal.domain.edu

Restarted Apache.

[root@KALTURA2 postfix]# /etc/rc.d/init.d/httpd restart
Stopping httpd:                                            [  OK  ]
Starting httpd: [Mon Nov 04 07:49:10 2019] [warn] module ssl_module is already loaded, skipping
                                                           [  OK  ]
[root@KALTURA2 postfix]# /etc/rc.d/init.d/httpd status
httpd (pid  949) is running...

“sendmail_path” is good.

[root@KALTURA2 postfix]# grep sendmail_path /etc/php.ini
sendmail_path = /usr/sbin/sendmail -t -i
[root@KALTURA2 postfix]# ls -l /usr/sbin/sendmail
lrwxrwxrwx 1 root root 21 Apr 23  2017 /usr/sbin/sendmail -> /etc/alternatives/mta
[root@KALTURA2 postfix]# file /etc/alternatives/mta
/etc/alternatives/mta: symbolic link to `/usr/sbin/sendmail.postfix'


I put this PHP file at /opt/kaltura/app/admin_console/web/testmail.php and ran it by going to https://kaltura2.domain.edu/admin_console/testmail.php

<?php     
$to_email = 'mbpowell @ domain . edu';
$subject = 'Testing PHP Mail';
$message = 'This mail is sent using the PHP mail function';
$headers = 'From: blah @ domain . edu';
mail($to_email,$subject,$message,$headers);
?>

I got the message:

Nov  4 08:37:03 smtp-relay-internal postfix/smtpd[9446]: connect from kaltura2.domain.edu[8.8.8.8]
Nov  4 08:37:03 smtp-relay-internal postfix/smtpd[9446]: BC103BEE10: client=kaltura2.domain.edu[8.8.8.8]
Nov  4 08:37:03 smtp-relay-internal postfix/cleanup[9449]: BC103BEE10: message-id=<20191104143703.ACFBC180EDA@KALTURA2.DOMAIN.EDU>
Nov  4 08:37:03 smtp-relay-internal postfix/qmgr[1181]: BC103BEE10: from=, size=620, nrcpt=1 (queue active)
Nov  4 08:37:03 smtp-relay-internal postfix/smtpd[9446]: disconnect from kaltura2.domain.edu[8.8.8.8] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Nov  4 08:37:07 smtp-relay-internal postfix/smtp[9450]: BC103BEE10: to=, relay=smtp-relay.domain.edu[1.1.1.1]:25, delay=3.8, delays=0/0/3.6/0.19, dsn=2.0.0, status=sent (250 2.0.0 2w1qk3uc3v-1 Message accepted for

There are no DEBUG level messages in /opt/kaltura/log/batch/bulkdownloadcloser*.log. The last one zipped up was from June of 2018.
/opt/kaltura/log/batch/bulkdownloadcloser-0-2018-06-29.log.1.gz
No DEBUG messages in /opt/kaltura/log/kaltura_batch.log, either.

jess · November 14, 2019, 10:55am

Hello @mpowell,

The fact we have no recent logs for this process would indicate that the relevant batch worker is disabled (or didn’t run for another reason).

What’s the output for:

# grep BulkDownloadCloser /opt/kaltura/app/configurations/batch/batch.ini
And also:
# grep bulkdownloadcloser -i /opt/kaltura/log/kaltura_batch.log
?

mpowell · November 14, 2019, 1:37pm

Hello @jess,
Here is the output for those two commands:


[root@KALTURA2 postfix]# grep BulkDownloadCloser /opt/kaltura/app/configurations/batch/batch.ini
enabledWorkers.KAsyncBulkDownloadCloser                 = 1
[KAsyncBulkDownloadCloser : JobCloserWorker]
type                                            = KAsyncBulkDownloadCloser
scriptPath                                          = batches/BulkDownload/KAsyncBulkDownloadCloserExe.php
[root@KALTURA2 postfix]# grep bulkdownloadcloser -i /opt/kaltura/log/kaltura_batch.log
[root@KALTURA2 postfix]#


Thank you,
Mark

jess · November 14, 2019, 1:49pm

Hi @mpowell,

According to the output from the first grep command, the relevant batch worker is enabled but the fact the second grep returned no results means it was not invoked recently.

Is the batch daemon running on this machine? Do you see lines in /opt/kaltura/log/kaltura_batch.log that match the pattern "ERR:\|PHP \|Stack trace:\|CRIT\|\[error\]"?

mpowell · November 14, 2019, 2:11pm

Hi @jess,
I see many error messages like the following:


PHP Fatal error:  Uncaught exception 'Zend_Config_Exception' with message 'Section 'KALTURA2.DOMAIN.EDU' cannot be found in /opt/kaltura/app/cache//batch/
config.ini' in /opt/kaltura/app/vendor/ZendFramework/library/Zend/Config/Ini.php:150

Thank you,
Mark

mpowell · November 14, 2019, 2:38pm

Hi @jess,
Looking in /opt/kaltura/app/cache/batch/config.ini, I find the following line is not commented out, and it’s Windows stuff:


params.expEncoderCmd = "C:\My\expressionencoder\RunAffinityCmd.exe 1 36000000 powershell -file C:\web\kaltura\batch\batches\Convert\scripts\runee3.ps1 C:\My\expressionencoder\ExpressionEncoder.dll"

Thanks,
Mark

jess · November 14, 2019, 5:18pm

Hi @mpowell,

That specific directive is irrelevant but:

PHP Fatal error:  Uncaught exception 'Zend_Config_Exception' with message 'Section 'KALTURA2.DOMAIN.EDU' cannot be found in /opt/kaltura/app/cache//batch/
config.ini' in /opt/kaltura/app/vendor/ZendFramework/library/Zend/Config/Ini.php:150

Is critical and means your batch daemon is not running at all.

Please see:

You didn’t state whether you’re using the deb or RPM packages. If RPM, running:

# /opt/kaltura/bin/kaltura-batch-config.sh

Should fix it.
For deb:

# dpkg-reconfigure kaltura-batch

Cheers,

mpowell · November 14, 2019, 5:51pm

Thank you, Jess,
Our server is running CentOS 6.10, so I ran the former command. Here is the output:


[root@KALTURA2 postfix]# /opt/kaltura/bin/kaltura-batch-config.sh
kaltura-batch-10.16.0-1.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

jess · November 14, 2019, 6:06pm

And is the batch daemon running now?

mpowell · November 14, 2019, 6:20pm

Jess,
I manually started it with /etc/init.d/kaltura-batch, then checked the log. I get the same messages as those logged after I tried to download a video a while ago.


[root@KALTURA2 postfix]# /etc/init.d/kaltura-batch start
Starting:[FAILED]
Service batch isn't running but stale lock file exists
Removing stale lock file at /opt/kaltura/log/batch/batch.pid
/usr/bin/php KGenericBatchMgr.class.php /usr/bin/php /opt/kaltura/app/configurations/batch >> /opt/kaltura/log/kaltura_batch.log 2>&1 &
[ OK ]
[root@KALTURA2 postfix]# /etc/init.d/kaltura-batch status
Service Batch isn't running
[root@KALTURA2 postfix]# tail /opt/kaltura/log/kaltura_batch.log
2019-11-14 12:32:43 [556803249] [KSchedulerConfig->load] NOTICE: loading configuration /opt/kaltura/app/configurations/batch at 1524169056
PHP Fatal error:  Uncaught exception 'Zend_Config_Exception' with message 'Section 'KALTURA2.DOMAIN.EDU' cannot be found in /opt/kaltura/app/cache//batch/config.ini' in /opt/kaltura/app/vendor/ZendFramework/library/Zend/Config/Ini.php:150
Stack trace:
#0 /opt/kaltura/app/batch/scheduler/KSchedulerConfig.class.php(59): Zend_Config_Ini->__construct('/opt/kaltura/ap...', 'KALTURA2.DOMAIN...', true)
#1 /opt/kaltura/app/batch/scheduler/KSchedulerConfig.class.php(42): KSchedulerConfig->load()
#2 /opt/kaltura/app/batch/scheduler/KGenericScheduler.class.php(88): KSchedulerConfig->__construct('/opt/kaltura/ap...')
#3 /opt/kaltura/app/batch/scheduler/KGenericScheduler.class.php(70): KGenericScheduler->loadConfig('/opt/kaltura/ap...')
#4 /opt/kaltura/app/batch/KGenericBatchMgr.class.php(37): KGenericScheduler->__construct('/usr/bin/php', '/opt/kaltura/ap...')
#5 {main}
  thrown in /opt/kaltura/app/vendor/ZendFramework/library/Zend/Config/Ini.php on line 150

jess · November 14, 2019, 6:22pm

Hello @mpowell,

In /opt/kaltura/app/configurations/batch/batch.ini, there’s a section that should look like this:

[HOSTNAME : mainTemplate]

What’s the hostname you see there?

mpowell · November 14, 2019, 6:40pm

Jess,
That file is missing. However, there is a batch.ini with the correct hostname. See below.

 
[root@KALTURA2 postfix]# ls -l /opt/kaltura/app/configurations/batch.ini
ls: cannot access /opt/kaltura/app/configurations/batch.ini: No such file or directory
[root@KALTURA2 postfix]# grep mainTemplate /opt/kaltura/app/configurations/batch/batch.ini
[kaltura2.tamhsc.edu : mainTemplate]
[root@KALTURA2 postfix]# dig kaltura2.tamhsc.edu | grep IN.*CNAME
kaltura2.tamhsc.edu. 3600       IN     CNAME    kaltura2.srv.tamhsc.edu.

mpowell · November 14, 2019, 8:23pm

Jess,
Apparently the batch daemon didn’t like that CNAME record. I put in the A record, instead, which is the FQHN and the daemon started!


[root@KALTURA2 postfix]# grep -B 1 KALTURA2 /opt/kaltura/app/configurations/batch/batch.ini
;[kaltura2.tamhsc.edu : mainTemplate]
[KALTURA2.SRV.TAMHSC.EDU : mainTemplate]
[root@KALTURA2 postfix]# /etc/init.d/kaltura-batch start
Starting:Batch is running as 13917 13918 13920 13922 13924 13926 13928 13930 13932 13934 13936 13938 13940 13942 13944 13947 13949 13952 13992 13997 13999 14001 14017 14019 14021 14023 14025 14032 without a /opt/kaltura/log/batch/batch.pid
[root@KALTURA2 postfix]# /etc/init.d/kaltura-batch status
Batch is running as 13917 14075 14077 ...
[root@KALTURA2 postfix]# tail /opt/kaltura/log/kaltura_batch.log
2019-11-14 14:24:25 [1729573278] [KProcessWrapper->init] DEBUG: Now executing...blah, blah, blah.

jess · November 15, 2019, 2:56pm

Hi @mpowell,

That’s good. And yes, the batch code calls PHP’s gethostname(): https://www.php.net/manual/en/function.gethostname.php

The value in batch.ini needs to match whatever is returned from it.
I trust you also receive the emails now?

mpowell · November 18, 2019, 5:41pm

Hi, Jess,
A content editor tried to download a video and still did not get the link in an e-mail.

I don’t see any errors in /opt/kaltura/log/kaltura_batch.log…

jess · November 18, 2019, 6:29pm

Hi @mpowell,

Were the /opt/kaltura/log/batch/bulkdownloadcloser*.log logs created? If so, what’s in them? If they weren’t, what does:

# grep bulkdownloadcloser -i /opt/kaltura/log/kaltura_batch.log
return now? Do you see an attempt to run this worker?

mpowell · November 18, 2019, 6:52pm

Hi Jess,
They were created:


[root@KALTURA2 ~]# ls -l /opt/kaltura/log/batch/bulkdownloadcloser*.log
-rw-r--r-- 1 kaltura kaltura    0 Nov 17 03:07 /opt/kaltura/log/batch/bulkdownloadcloser-0-2019-11-17.err.log
-rw-r--r-- 1 kaltura kaltura 2695 Nov 17 03:07 /opt/kaltura/log/batch/bulkdownloadcloser-0-2019-11-17.log

Here is what is in the only one to be written to:


[root@KALTURA2 ~]# cat /opt/kaltura/log/batch/bulkdownloadcloser-0-2019-11-17.log
2019-11-17 03:07:51 [269754972] [KBatchBase->__construct] DEBUG: ___________________________________________________________________________________
2019-11-17 03:07:51 [269754972] [KBatchBase->__construct] INFO: 2.0.2
2019-11-17 03:07:51 [269754972] [KBatchBase->__construct] DEBUG: set_time_limit({300})
2019-11-17 03:07:51 [269754972] [KBatchBase->__construct] DEBUG: This batch index: 0
2019-11-17 03:07:51 [269754972] [KBatchBase->__construct] DEBUG: This session key: sess5dd10de7bda7d
2019-11-17 03:07:51 [269754972] [KJobHandlerWorker->saveQueueFilter] DEBUG: Saving filter to KAsyncBulkDownloadCloser.flt: KalturaWorkerQueueFilter Object
(
    [schedulerId] => 33178
    [workerId] => 150
    [jobType] => 19
    [filter] => KalturaBatchJobFilter Object
        (
            [idEqual] =>
            [idGreaterThanOrEqual] =>
            [partnerIdEqual] =>
            [partnerIdIn] =>
            [partnerIdNotIn] =>
            [createdAtGreaterThanOrEqual] =>
            [createdAtLessThanOrEqual] =>
            [updatedAtGreaterThanOrEqual] =>
            [updatedAtLessThanOrEqual] =>
            [executionAttemptsGreaterThanOrEqual] =>
            [executionAttemptsLessThanOrEqual] =>
            [lockVersionGreaterThanOrEqual] =>
            [lockVersionLessThanOrEqual] =>
            [entryIdEqual] =>
            [jobTypeEqual] => 19
            [jobTypeIn] =>
            [jobTypeNotIn] =>
            [jobSubTypeEqual] =>
            [jobSubTypeIn] =>
            [jobSubTypeNotIn] =>
            [statusEqual] => 8
            [statusIn] =>
            [statusNotIn] =>
            [priorityGreaterThanOrEqual] =>
            [priorityLessThanOrEqual] =>
            [priorityEqual] =>
            [priorityIn] =>
            [priorityNotIn] =>
            [batchVersionGreaterThanOrEqual] =>
            [batchVersionLessThanOrEqual] =>
            [batchVersionEqual] =>
            [queueTimeGreaterThanOrEqual] =>
            [queueTimeLessThanOrEqual] =>
            [finishTimeGreaterThanOrEqual] =>
            [finishTimeLessThanOrEqual] =>
            [errTypeEqual] =>
            [errTypeIn] =>
            [errTypeNotIn] =>
            [errNumberEqual] =>
            [errNumberIn] =>
            [errNumberNotIn] =>
            [estimatedEffortLessThan] =>
            [estimatedEffortGreaterThan] =>
            [urgencyLessThanOrEqual] =>
            [urgencyGreaterThanOrEqual] =>
            [orderBy] =>
            [advancedSearch] =>
            [relatedObjects] =>
        )

    [relatedObjects] =>
)

The only action occurred over the weekend, on the 17th. The user requested the download on the afternoon of Thursday the 14th. I also logged on as my content producer account and requested a download, and never got the e-mail.

Here is what grep bulkdownloadcloser -i /opt/kaltura/log/kaltura_batch.log shows:


[root@KALTURA2 ~]# grep bulkdownloadcloser -i /opt/kaltura/log/kaltura_batch.log
2019-11-17 03:07:51 [704025645] [KGenericScheduler->initSingleWorker] INFO: Initilizing KAsyncBulkDownloadCloser
2019-11-17 03:07:51 [704025645] [KProcessWrapper->init] DEBUG: Now executing [setsid /usr/bin/php /opt/kaltura/app/batch/batches/BulkDownload/KAsyncBulkDownloadCloserExe.php eJzFVdtu2zgQ7acUeiyw1s2OXfmljuMg3qZJYTktsC8GLY4iwhSppajGbpF/75Ai4/SaxWIXebHkM8PhmTMXXWdJlAVv86IC2nGi1qTdzaUo2W2QxUn2pTW/wYtXL/7uoIOcfYZgyrJoivjY4hsBrc6hIYpoqQJjyIKBeZrAxqGFQjMpvvfJ7HPkfHasWew1CNoG062Nn/T3bgjn8u6dpKxkBTGBrEeMHq97ByYo7D0rhxWyE9pgyQTBSQ9SokkwJYiZvAy9muxZ3dWLPRSdCb1mNRhaaRakUWTeTrLA0K7x0ussRtp/IceNV6gP9N8Q/QlPKz/KrKFuzphCHaU6vCe6stIhtVA2OtwRrjtFQl03gasL5mVSOYVSKjgnjBsDSh1HkUnrHknHR+GvYK+XGpQlHUyvHhWXS0KB5n0FncmdBF8ukkXZl/tjvc2Zc8ZhoZRUuVbmGJpjFBXELRNw3Th1/l9F4x8Vja2iKBxpG8x3jbqeS07B9mQa/Sho2DtuusZk9VzKoRwFZyC0U+mZhEO/T6BYecjzSzfEz9ZM2Mylgfes1SvQDFrHKPUz8GBeCqTziXDnMLLPoR2SP+W2XZCiWnXCbiwzIe6FUbcI4pGFTBFKhUWg/HBF+jVhSJ52fPfyTN4Jw/TlnMu27ya8QB+a3g3f387agyiMs/c9usYYpi0Ua7Sf7RFetiUal3IbPj4T/ioMbrBBUzXuYuH5PXVxYlVYilYTUTxIGAd9U+Di0wLUkjpJ/ojdRsSNrkBbfRAGMkyggPF2VKbRmI5gRNNhOqGTsiwgGdpDps5Fp7jZSrLTXtpJ5I1t/wHyt2F50zQeT6w5fWR+kD41qV2ub1azZJCvPgzWs3cX+XywOLt5kBSrzgq4UbbyKV5Sad20WegHPBloUldtMcDQ2XBoOwcbh95Vvg5GwG9WApe3IdoH+PRtRP1inle19E0zHo9cGsUj9ORk6MlhkIUgWw70OEl26jQq9FkK8F/HWY0jV5BwXuHvrXReTDB9LfjBj7XxVFBLDTlmDcolbZR9czpbzy82N6vLNx4yNacc+q/dVV9sjR/+5XEr/Ouptrui3yu/b7/7n05/atfYU32L2eLo9sBHqXa/h08sfEFwdP8JjrD/89Qi+goKl96G '[1954375710]' >> /opt/kaltura/log/batch//bulkdownloadcloser-0-2019-11-17.log 2>> /opt/kaltura/log/batch//bulkdownloadcloser-0-2019-11-17.err.log]
2019-11-17 03:07:52 [704025645] [KGenericScheduler->shouldExecute] DEBUG: Worker [KAsyncBulkDownloadCloser] id [150] running batches [1] max instances [1]