OP25 Cannot start liquidsoap

[maredzki]

I have OP25 running on rpi3b+ but for some reason cannot get liquidsop to start streaming to broadcastify. Here is the log from systemctl status.

pi@raspberrypi:~/op25/op25/gr-op25_repeater/apps $ sudo systemctl status op25-liq.service
● op25-liq.service - op25-liq
   Loaded: loaded (/etc/systemd/system/op25-liq.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Thu 2020-04-30 16:50:38 CDT; 2min 52s ago
  Process: 1086 ExecStart=/usr/bin/liquidsoap op25.liq (code=exited, status=0/SUCCESS)
 Main PID: 1086 (code=exited, status=0/SUCCESS)

Apr 30 16:50:36 raspberrypi systemd[1]: Started op25-liq.
Apr 30 16:50:37 raspberrypi liquidsoap[1086]: 2020/04/30 16:50:37 >>> LOG START
Apr 30 16:50:37 raspberrypi liquidsoap[1086]: 2020/04/30 16:50:37 [main:3] Liquidsoap 1.3.3
Apr 30 16:50:37 raspberrypi liquidsoap[1086]: 2020/04/30 16:50:37 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.2.3 dtools=0.4.0 duppy=0.7.2 duppy.syntax=0.7.2 cry=0.6.2 mm=0.3.1 xmlp
Apr 30 16:50:37 raspberrypi liquidsoap[1086]: 2020/04/30 16:50:37 [gstreamer.loader:3] Loaded GStreamer 1.14.4 0
Apr 30 16:50:37 raspberrypi liquidsoap[1086]: 2020/04/30 16:50:37 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder.
Apr 30 16:50:37 raspberrypi liquidsoap[1086]: 2020/04/30 16:50:37 [clock.wallclock_pulse:2] Error when starting output pulse_out(liquidsoap:): Pulseaudio error: Connection refused!
Apr 30 16:50:37 raspberrypi liquidsoap[1086]: 2020/04/30 16:50:37 >>> LOG END
Apr 30 16:50:38 raspberrypi systemd[1]: op25-liq.service: Succeeded.

Any help would be greatly appreciated!

Thank you,
Marek

 

[boatbod]

It's a pulseaudio problem.

Apr 30 16:50:37 raspberrypi liquidsoap[1086]: 2020/04/30 16:50:37 [clock.wallclock_pulse:2] Error when starting output pulse_out(liquidsoap: Pulseaudio error: Connection refused!

Not sure how you have you .liq script configured, but I would suggest you either disable local audio or uninstall/reinstall pulseaudio.

 

[maredzki]

Here is my op25.sh script:

./rx.py -l http:127.0.0.1:8080 --args 'rtl' -N 'LNA:47' -O loop0 -S 960000 -o 25000 -q -1 -d 300 -T trunk.tsv -V -2 -w -M meta.json 2> stderr.log

Here is op25.liq file

#!/usr/bin/liquidsoap

# Example liquidsoap streaming from op25 to icecast
# (c) 2019, gnorbury@bondcar.com
#

set("log.stdout", true)
set("log.file", false)
set("log.level", 2)

# Make the native sample rate compatible with op25
set("frame.audio.samplerate", 8000)

input = mksafe(input.external(buffer=0.02, channels=2, samplerate=8000, restart_on_error=false, "./audio.py -s"))
# Consider increasing the buffer value on slow systems such as RPi3. e.g. buffer=0.25
# Longer buffer results in less choppy audio but at the expense of increased latency.

# LOCAL AUDIO
# Uncomment the appropriate line below to enable local sound
#
# Default audio subsystem
out (input)
#
# PulseAudio
#output.pulseaudio(input)
#
# ALSA
#output.alsa(input)


# ICECAST STREAMING
# Uncomment to enable output to an icecast server
# Change the "host", "password", and "mount" strings appropriately first!
# For metadata to work properly, the host address given here MUST MATCH the address in op25's meta.json file
#
#output.icecast(%mp3(bitrate=16, samplerate=22050, stereo=false), description="op25", genre="Public Safety", url="", fallible=false, icy_metadata="false", host="localhost", port=8000, mount="mountpoint", password="hackme", mean(input))

 

[boatbod]

With pulseaudio still installed, you could comment out the default audio destination and uncomment the ALSA destination, that way liquidsoap would use alsa rather than pulse.

# LOCAL AUDIO
# Uncomment the appropriate line below to enable local sound
#
# Default audio subsystem
#out (input)
#
# PulseAudio
#output.pulseaudio(input)
#
# ALSA
output.alsa(input)

 

[maredzki]

Did as you recommended but still showing status "In Transition" over at broadcastify.

I'm also getting this notification on liquidsoap status. Could that be a cause?

liquidsoap[2818]: 2020/05/01 11:23:47 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder.

 

[boatbod]

Did as you recommended but still showing status "In Transition" over at broadcastify.

I'm also getting this notification on liquidsoap status. Could that be a cause?

liquidsoap[2818]: 2020/05/01 11:23:47 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder.

That last message can be ignored.

Do you see anything is /var/log/liquidsoap ?

 

[maredzki]

That last message can be ignored.

Do you see anything is /var/log/liquidsoap ?

err.... that folder is empty....

I'm enabling it via op25.liq... i'll be right back...

 

[maredzki]

In op25.liq set set("log.file", true) but still no log. I must be in the wrong spot.

set("log.stdout", true)
set("log.file", true)
set("log.level", 3)

 

[boatbod]

It might be in the /var/log directory inside the syslog file.

cd /var/log
grep -i liquidsoap

 

[maredzki]

Indeed, here it is:

May  1 16:57:30 raspberrypi systemd[1]: Started op25-liq.
May  1 16:57:31 raspberrypi liquidsoap[3812]: init: exception encountered during start phase:
May  1 16:57:31 raspberrypi liquidsoap[3812]:   Sys_error("/var/log/liquidsoap/op25.log: Permission denied")
May  1 16:57:31 raspberrypi systemd[1]: op25-liq.service: Main process exited, code=exited, status=255/EXCEPTION
May  1 16:57:31 raspberrypi systemd[1]: op25-liq.service: Failed with result 'exit-code'.

 

[boatbod]

Indeed, here it is:

May  1 16:57:31 raspberrypi liquidsoap[3812]:   Sys_error("/var/log/liquidsoap/op25.log: Permission denied")

Might need to pick a different non-privileged area to put the log since liquidsoap is running as a user not root.

 

[maredzki]

Ok, created the log and it is now dumping this info:

2020/05/01 19:41:44 [threads:3] Created thread "alsa_out(default)" (1 total).
2020/05/01 19:41:44 [threads:3] Created thread "wallclock_alsa" (2 total).
2020/05/01 19:41:44 [clock.wallclock_alsa:3] Streaming loop starts, synchronized by active sources.
2020/05/01 19:41:44 [mksafe:3] Switch to safe_blank.
2020/05/01 19:41:44 [alsa_out(default):3] Using ALSA 1.1.8.
2020/05/01 19:41:44 [alsa_out(default):3] Samplefreq=8000Hz, Bufsize=32768B, Frame=4B, Periods=128
2020/05/01 19:41:54 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/01 19:41:54 [mksafe:3] Switch to safe_blank with transition.
2020/05/01 19:42:04 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/01 19:42:04 [mksafe:3] Switch to safe_blank with transition.
2020/05/01 19:42:14 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/01 19:42:14 [mksafe:3] Switch to safe_blank with transition.
2020/05/01 19:42:24 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/01 19:42:24 [mksafe:3] Switch to safe_blank with transition.
2020/05/01 19:42:34 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/01 19:42:34 [mksafe:3] Switch to safe_blank with transition.
2020/05/01 19:42:44 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/01 19:42:44 [mksafe:3] Switch to safe_blank with transition.

 

[boatbod]

Looks like it's working.
The switches to safe_blank occur at the end of a received voice burst.

 

[maredzki]

Hmm... interesting, broadcastify still says "In Transition"

 

[boatbod]

Let me back up a little.... liquidsoap is actively receiving from op25 and mksafe() is filling the stream in between transmissions. Whether or not liquidsoap is sending to broadcastify is not something I can ascertain from the log fragment attached to your post. You'll need to look at the complete liquidsoap log and see if the broadcastify server is refusing connection.

If you have metadata configured on op25 you may also be able to use metadata transmission success or failure as a metric. If the stream is down the server will refuse incoming metadata updates from op25.

 

[maredzki]

Thank you and I apologize for bugging you about it.

I am looking through both /var/log/syslog and my liquidsoap.log file and don't seem to find any errors. I've increased liquidsoap log to 5 and am getting the following, but still no errors or warnings.

pi@raspberrypi:~/op25/op25/gr-op25_repeater/apps $ tail -f /home/pi/liquidsoap/log.log
2020/05/04 11:22:49 [alsa_out(default):3] Samplefreq=8000Hz, Bufsize=32768B, Frame=4B, Periods=128
2020/05/04 11:22:49 [input.external_7212:5] audio device: stdout

2020/05/04 11:23:03 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 11:23:03 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:03 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:03 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 11:23:03 [mksafe:3] Switch to safe_blank with transition.
2020/05/04 11:23:03 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:03 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:13 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 11:23:13 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:13 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:13 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 11:23:13 [mksafe:3] Switch to safe_blank with transition.
2020/05/04 11:23:13 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:13 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:23 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 11:23:23 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:23 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:23 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 11:23:23 [mksafe:3] Switch to safe_blank with transition.
2020/05/04 11:23:23 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:23 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:33 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 11:23:33 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:33 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:33 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 11:23:33 [mksafe:3] Switch to safe_blank with transition.
2020/05/04 11:23:33 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:33 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:43 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 11:23:43 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:43 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:43 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 11:23:43 [mksafe:3] Switch to safe_blank with transition.
2020/05/04 11:23:43 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:43 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:53 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 11:23:53 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:53 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:53 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 11:23:53 [mksafe:3] Switch to safe_blank with transition.
2020/05/04 11:23:53 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:23:53 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:24:03 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 11:24:03 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:24:03 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:24:03 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 11:24:03 [mksafe:3] Switch to safe_blank with transition.
2020/05/04 11:24:03 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 11:24:03 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].

 

[boatbod]

In your op25.liq script file have you uncommented the "output.icecast" entry (by removing the '#') and set it up to match your feed?

 

[maredzki]

Ofcourse not, why would I??? Duh!

Enabled it and now Broadcastify switched to "Online". I haven't checked what quality is coming out yet.

I checked the README-rpi3-liquidsoap and I couldn't find those steps that we had to go through here, maybe they should be added in?

In op25.liq
Uncomment output.alsa(input)
# ALSA
output.alsa(input)

Uncocomment
output.icecast(%mp3(bitrate=16, samplerate=22050, stereo=false), description="op25", genre="Public Safety", url="", fallible=false, icy_metadata="false", host="", port=80, mount="", password="", mean(input))

Just a thought.

Thank you sincerely!

 

[maredzki]

After some time I'm getting the following in the log and broadcastify sends me a down notification:

pi@raspberrypi:~/op25/op25/gr-op25_repeater/apps $ tail -f /home/pi/liquidsoap/log.log
2020/05/04 12:28:57 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 12:28:57 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 12:28:59 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 12:28:59 [mksafe:3] Switch to safe_blank with transition.
2020/05/04 12:28:59 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 12:28:59 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 12:29:01 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 12:29:01 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 12:29:01 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 12:29:01 [input.external_7212:4] End of track.

 

[maredzki]

It happened again, where "End of track" ocurred and the stream was interrupted. Any ideas?

2020/05/04 14:39:14 [mksafe:3] Switch to safe_blank with forgetful transition.
2020/05/04 14:39:14 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 14:39:14 [safe_blank:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 14:39:16 [mksafe:3] Switch to input.external_7212 with transition.
2020/05/04 14:39:16 [safe_blank:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 14:39:16 [input.external_7212:4] Activations changed: static=[mksafe:alsa_out(default):alsa_out(default)], dynamic=[mksafe:alsa_out(default):alsa_out(default)].
2020/05/04 14:39:16 [input.external_7212:4] End of track.
2020/05/04 14:39:16 [input.external_7212:4] Buffer emptied, buffering needed.
2020/05/04 14:39:16 [mksafe:3] Switch to safe_blank with forgetful transition.
2020/05/04 14:39:16 [input.external_7212:4] Activations changed: static=[], dynamic=[mksafe:alsa_out(default):alsa_out(default)].