Sebastian's picture

Hello everyone,

I recently installed Espo CRM on our Proxmox Server by using this LXC Container 

I also have a Starface phone server which I want to connect to Espo CRM.

Unfortunately I ran into trouble with the cron job, communicating between the starface server and espo.

It should work like that:

Ingoing or outgoing calls triggers Starface to initialize the call and at the same time Espo shows a pop window where I can take notes.

Outgoing calls are working fine. I select the phone number within Espo, the call gets initialized on the starface server and the Pop Up appears where I can make my notations.

But the ingoing calls don't work that way. Only a short time after I made an outgoing call, do incoming calls get recognised and the pop up shows up. But after a few minutes, no incoming calls are recognised by espo whatsoever.
 

I already tried to get help on the Espo forum with no luck. Furthermore did I try to directly contact the support team of Espo. But they couldn't solve the problem either and mentioned to geht help by turnkey, the provider of the container.

 

So here I am, desperately looking for help.

Any advice is much appreciated. Thanks in advance

 

Regards

Sebastian

Forum: 
Jeremy Davis's picture

Hi Sebastian, welcome to TurnKey. I'll certainly try my best to help get your going, but in an effort to temper your expectations, I'll like to give you our context.

We are a small team that provide a library of over 100 software appliances, using a variety of different languages and technologies. EspoCRM is just one, pre-installed to our mildly customised Debian OS. So whilst we have a deep understanding of Debian and of the minor tweaks and (IMO) improvements that we provide in our base OS, we're certainly not the experts of EspoCRM. TBH, I've never actually even used it. In other words, our knowledge tends to be broad, rather than deep. If EspoCRM community and/or support themselves can't work it out, then TBH I'm not feeling super confident...

Regardless, to give you my best effort, I need to understand the issue. To help short circuit that a bit, could you please point to your previous discussions with EspoCRM community/team (e.g. forum posts etc) and any docs you've consulted and/or other further info?

FWIW, I just googled "espocrm cron issues" and got overwhelmed with results which are clearly irrelevant and not specific to you. In an effort to understand a bit more about your setup, I also googled "starface" and could only find skincare products?! I retried with "starface server" and found out that it's a Asterisk based VoIP OS/system (which sounds likely! I also stumbled across the EspoCRM Starface Integration Setup docs. So I feel fairly confident I'm on the right track.

So for future reference, you could have saved me an hour or so by providing a bit more info. As a general rule you can never provide too much info when seeking technical support, especially when done asynchronously. Support people are really good at filtering out info that is irrelevant, but not so good at divining info you haven't provided...! :)

Regardless, I'll have a vaguely informed guess at what might work...


Armed with a bit of context of your setup and your reference to a cron job, I'll have a crack (TBH initially I didn't even understand what the connection between your issue and a cron job was?!). Straight off the bat, it doesn't actually say where/how to create that cron job, so I have no idea what you've actually done and/or tried?!

Without that knowledge, I can only suggest that you undo what you've done and start fresh. Personally, I prefer to put system level cron jobs in /etc/cron.d. So here's what I would do to create the cron job noted at step 2 of the EspoCRM Starface Integration docs. Note that this is from the commandline of your server, running as root (e.g. logged in as root via SSH):

cat > /etc/cron.d/espo-starface /dev/null 2>&1
EOF

If that doesn't appear to resolve your issue and you want to see any likely issues, then tweak the last part to write to a log file (instead of /dev/null - which is essentially just a black hole). Just change the '> /dev/null', to '>> /var/www/espocrm/starface-cron.log' and it will write to a file; /var/www/espocrm/starface-cron.log. It will likely generate heaps of data and end up quite large, so be sure to change it back as soon as you've gained the needed insight. You could edit the existing cron job, or just overwrite it (with one that logs), like this:

cat > /etc/cron.d/espo-starface >/var/www/espocrm/starface-cron.log 2>&1
EOF

Then you can check the (last 50 lines of the) log file, like this:

tail -50 /var/www/espocrm/starface-cron.log

If that's just too noisy, then you could make it write just the stderr (standard error output - generally error only output) to the log and dump the stdout (standard output). Overwrite the previous file like this:

cat > /etc/cron.d/espo-starface /dev/null 2>>/var/www/espocrm/starface-cron.log

Please be sure to change it back to the original one after you've collected info. Assuming that doesn't actually fix your issue, please share info from that log file (copy paste into a new post, or upload a file attached to your first post - be sure to tell me if you do that) here and I can assist interpret it.

Sebastian's picture

Hi Jeremy,

first of all, many thanks for your quick and detailed reply.

Sorry I didn't give you a clearer picture and caused you that much trouble.

 

Anyhow, I followed your advice and tweaked the command in order to write a log file . To my suprise the log file was empty after executing the command. 

So I think the problem is not the cron job which triggers this command, but the command itself.

 

To give you a better understanding of my problem, please take a look at my initial description:

Hello everyone,

unfortunately, I have a problem regarding my integration of the starface phone system.
I already tried to solve my issue on the forum, but with no luck so far
https://forum.espocrm.com/forum/extensions/75985-error-voip-pop-up-after-update

Here is what happen:

Outgoing calls are working fine. I select the phone number within Espo, the call gets initialised on the starface server and the Pop Up appears where I can make my notations.

But the ingoing calls don't work that way. Only a short time after I made an outgoing call, do incoming calls get recognised and the pop up shows up.
After a few minutes no incoming calls are recognised by espo.
I guess that somehow, the connection with the starface system is falling asleep.

I made some log files with debug mode activated. Hopefully they can give you some insight what exactly is going wrong.

Here you can find the log files.

 

Again many thanks for your support.

Best regards

Sebastian

 

Jeremy Davis's picture

That certainly sounds weird.

It's Saturday morning for me so I've only quickly scanned through your message. I have a bit on this weekend, but if I get a chance I'll have a proper look when I can. Otherwise, it'll be Monday morning. Take care and have a great weekend.

Jeremy Davis's picture

So I've had a look through your thread on EspoCRM forums and browsed your log files. That does give me a bit more context, but TBH, I'm not really sure what might be going on.

As you noted in your EspoCRM thread, there does seem to be a lot of entries which say:

INFO: JobManager: Skip job processing. Too frequent execution. [] []

I'm not sure if that is related to your issue (or even whether it's actually an issue at all TBH), but I wonder if that is because there are multiple cron jobs trying to do that same thing? Assuming that your logs show times when it did work, then I suspect that is just noise?! (Probably worth trying to fix, but likely not related to your issue).

This may be stating the obvious, but the issue appears to be related to the communication between EspoCRM and Starface. If it wasn't working at all, I would be wondering if it was somehow related to running on LXC (because of technical limitations that can cause unexpected issues, although they should be consistent)? But considering that the issue is intermittent, suggests to me that is almost certainly not related to LXC.

TBH, this issue is way out of my area of expertise but I have a couple of troubleshooting techniques that may assist you to track down the issue (but you will still likely need EspoCRM team to assist with resolution).

The first thing that I would recommend (if you haven't already done it) is ensuring that you are running the latest release of EspoCRM. Before you do that, ensure that you have a backup. TKLBAM or Proxmox are options (or even just a Proxmox snapshot). Then according to the EspoCRM docs this should do the trick:

cd /var/www/espocrm
runuser www-data -s /bin/bash
php command.php upgrade
exit # exit back to root user

After than, the next thing that is worth checking IMO is to try manually running the command in the cron job. You can do that like this:

cd /var/www/espocrm
runuser www-data -s /bin/bash
php -f command.php voip Starface
echo $?
exit

Hopefully the PHP line might give some useful output? If it gives no output at all, look for the number printed after the 'echo $?' line. That will be the exit code of the php command. If it's anything other than zero, then some sort of error has occurred.

I imagine that will be fine, but it's probably worth checking.

Another thing to try is to compare logs from when it works, to when it doesn't work. One way to catch the relevant log snippets is to read the logs in realtime. To do that, in an SSH session, run the following command:

tail -f /var/log/apache2/error.log

That will "follow" the log in realtime, so new log entries will show up at the bottom as stuff happens. so get that running and get ready to call in. Just before you try calling, hit enter in the logs (to create a blank line so it's easier to see what is directly relevant). When you wish to stop viewing the log, then hit to exit.

Getting a clear log of when it's working should be fairly straight forward. When it's not working may be harder. My guess is that something happens (stops listening?) before it doesn't work. So if I'm right, then there may actually be nothing of value/interest in the logs when it doesn't work. but in that case it should be before the call in fails.

Re the logs you've shared, without knowing EspoCRM or Starface that well, I'm not really sure what I'm looking for. Having said that, I'm guessing that these sort of entries are when it's working:

[2021-11-22 14:49:27] INFO: Starface: KeepAlive user online [10]. [] []
[...]
[2021-11-22 14:49:49] DEBUG: Starface: Event from Starface server for Starface user [10]: END. [] []

(I only posted the first and last log entries of what I'm guessing is when it worked.)

Assuming that I am on the right track, I did notice this in the logs which I wonder if it's related?! (10 minutes before the above entry):

[2021-11-22 14:39:01] DEBUG: Starface: User[10] logged out. [] [] 

Sorry that that probably isn't super useful, but I'm way out of my league here. If you were having a problem with TurnKey itself I could definitely help, but I just don't know EspoCRM well enough and know almost zero about Starface.

Sebastian's picture

Hi Jeremy,

thanks for sharing your wisdom.

I think the problem comes from the starface server. Neither you, nor the guys from Espo can boil it down. Everything which should work from their end is going right.

My guess is the weird log out of the Starface User. It should keep the connection alive, which obviusly is not the case

I will give it another try to read the log files and hopefully find more usefull hints.

 

Anyhow, thanks for your time and your help.

Jeremy Davis's picture

You're most welcome. Sorry that I couldn't help more.

I reckon that you might be right re:

My guess is the weird log out of the Starface User. It should keep the connection alive, which obviusly is not the case

Actually, IIRC it was ~10 minutes of inactivity when it logs out? So my guess is that that's the Starface default (10 minutes?) timeout. I suspect that there may be some setting in Starface that you need to tweak to ensure that it doesn't log out when idle. It may even be some power saving functionality (if starface is running on bare metal - or even possibly dedicated VM; that would be unlikely in an LXC container IMO).

Good luck tracking it down. Please feel free to post back if you gather more info and want a second opinion. And please definitely post back with the fix if/when you work it out. I'm sure others will definitely benefit.

Sebastian's picture

The guys from espo came up with a solution to my problem.

It was a problem with the starface connection:

Starface: Fixed timeout issue when web-socket enabled.

With the latest Update everything is working smooth.

 

Thanks again for your help solving this issue.

 

Best regards

Sebastian

Add new comment