Libretime: Liquidsoap constantly failing

Created on 31 May 2017  Β·  27Comments  Β·  Source: LibreTime/libretime

Alpha1 + debian jessie

In stream configuration im getting:

Getting information from the server...

Than i mentioned that in status liquidsoap is marked as failed.
But service is running:

$ sudo service airtime-liquidsoap status
airtime-liquidsoap.service - LSB: Manage airtime-liquidsoap daemon
   Loaded: loaded (/etc/init.d/airtime-liquidsoap)
   Active: active (exited) since Π‘Ρ€ 2017-05-31 13:26:34 +03; 4min 42s ago
  Process: 29397 ExecStop=/etc/init.d/airtime-liquidsoap stop (code=exited, status=0/SUCCESS)
  Process: 29406 ExecStart=/etc/init.d/airtime-liquidsoap start (code=exited, status=0/SUCCESS)

ΠΌΠ°ΠΉ 31 13:26:34 raspberrypi airtime-liquidsoap[29406]: Starting airtime-liquidsoap: Done.
ΠΌΠ°ΠΉ 31 13:26:34 raspberrypi systemd[1]: Started LSB: Manage airtime-liquidsoap daemon.

than i found out that 

$ ls -la /etc/airtime/liquidsoap.cfg 
-rw-r--r-- 1 www-data www-data 3559 ΠΌΠ°ΠΉ 31 13:26 /etc/airtime/liquidsoap.cfg

is at defaults, and changes i make in backend does't change anything in config:

################################################
# THIS FILE IS AUTO GENERATED. DO NOT CHANGE!! #
################################################
# The ignore() lines are to squash unused variable warnings
s2_output = "icecast"
ignore(s2_output)
s2_genre = ""
ignore(s2_genre)
s1_port = 8000
ignore(s1_port)
s4_port = 8000
ignore(s4_port)
s1_admin_user = ""
ignore(s1_admin_user)
s4_admin_user = ""
ignore(s4_admin_user)
s1_liquidsoap_error = "waiting"
ignore(s1_liquidsoap_error)
s3_user = ""
ignore(s3_user)
s4_user = ""
ignore(s4_user)
s3_admin_user = ""
ignore(s3_admin_user)
s1_enable = true
ignore(s1_enable)
s1_mobile = "0"
ignore(s1_mobile)
s2_channels = "stereo"
ignore(s2_channels)
s2_url = ""
ignore(s2_url)

^^only 1 screen copy. ^^

what can i do?

discourse
Source
picture aresstokrat

All 27 comments

LT and AIrtime use a different config file than the Liquidsoap default. I would do a hard reboot and see if it persists.

ghost picture ghost on 31 May 2017

now i see that
Pypo
and
Media Analzyer

also failing time to time in status tab of admin panel.

i made hard reset, did't help.

aresstokrat picture aresstokrat on 31 May 2017

I would recommend first getting analyzer to work and then looking into playout/liquidsoap. Are there any additional logs in /var/log/airtime?

To figure out what analyzer is doing wrong you can stop the service and run it manually. With the debug flag it should output all logs to stdout and stay in the foreground.

sudo service airtime-liquidsoap stop
sudo -u www-data airtime_analyzer --debug

Once it is running, try uploading a file through the web interface and check if analyzer has anything helpful in it's output.

The admin status tab isn't very precise, if the services fail sporadically this is probably because they are trying to restart all the time.

If all fails you might want to look into using systemd files directly as being worked on in #173.

hairmare picture hairmare on 31 May 2017
👍1

i have:

tail /var/log/airtime/
airtime-celery.log  pypo-liquidsoap/    
pypo/               zendphp.log

sudo tail /var/log/airtime/pypo/notify.log 

#################################################
2017-05-31 15:07:26,108 [pyponotify] [INFO ]  msg = could not write data to host: Connection refused in write()
2017-05-31 15:07:26,390 [pyponotify] [INFO ]  Response: null
2017-05-31 15:07:32,078 [pyponotify] [INFO ]  #################################################
2017-05-31 15:07:32,079 [pyponotify] [INFO ]  # Calling server to update liquidsoap status    #
2017-05-31 15:07:32,080 [pyponotify] [INFO ]  #################################################
2017-05-31 15:07:32,080 [pyponotify] [INFO ]  msg = could not write data to host: Connection refused in write()
2017-05-31 15:07:32,282 [pyponotify] [INFO ]  Response: null

tail /var/log/airtime/airtime-celery.log 

[2017-05-31 12:27:38,604: INFO/MainProcess] mingle: all alone
[2017-05-31 12:27:38,748: WARNING/MainProcess] airtime-celery@raspberrypi ready.
[2017-05-31 12:34:58,432: INFO/MainProcess] Connected to amqp://airtime:**@127.0.0.1:5672//airtime
[2017-05-31 12:34:58,502: INFO/MainProcess] mingle: searching for neighbors
[2017-05-31 12:34:59,544: INFO/MainProcess] mingle: all alone
[2017-05-31 12:34:59,632: WARNING/MainProcess] airtime-celery@raspberrypi ready.
[2017-05-31 14:54:49,958: INFO/MainProcess] Connected to amqp://airtime:**@127.0.0.1:5672//airtime
[2017-05-31 14:54:50,031: INFO/MainProcess] mingle: searching for neighbors
[2017-05-31 14:54:51,069: INFO/MainProcess] mingle: all alone
[2017-05-31 14:54:51,162: WARNING/MainProcess] airtime-celery@raspberrypi ready.

sudo tail -100 /var/log/airtime/pypo-liquidsoap/ls_script.log 

2017/05/31 15:05:17 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496232179.67 &
2017/05/31 15:05:17 [_a:3] Will try again in 5.00 sec.
2017/05/31 15:05:23 [_a:3] Connecting mount _a for admin@localhost...
2017/05/31 15:05:23 [_a:2] Connection failed: could not write data to host: Connection refused in write()
2017/05/31 15:05:23 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496232179.67 &
2017/05/31 15:05:23 [_a:3] Will try again in 5.00 sec.
2017/05/31 15:05:29 [_a:3] Connecting mount _a for admin@localhost...
2017/05/31 15:05:29 [_a:2] Connection failed: could not write data to host: Connection refused in write()
2017/05/31 15:05:29 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496232179.67 &
2017/05/31 15:05:29 [_a:3] Will try again in 5.00 sec.

i did:
sudo service airtime-liquidsoap stop
sudo -u www-data airtime_analyzer --debug

uploaded the file, its still same error "import failed"

than i made
sudo service airtime-liquidsoap start
and uploaded file one more time, same error

the output:

sudo -u www-data airtime_analyzer --debug
Airtime Analyzer 1.0
2017-05-31 15:00:52,500 [select_connection] [DEBUG]  Using EPollPoller
2017-05-31 15:00:52,502 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551f288>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,503 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551f1e8>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,504 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551f238>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,505 [callback] [DEBUG]  Added: {'callback': <bound method SelectConnection._on_connection_start of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,506 [base_connection] [INFO ]  Connecting to 127.0.0.1:5672
2017-05-31 15:00:52,511 [callback] [DEBUG]  Processing 0:Connection.Start
2017-05-31 15:00:52,512 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,513 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,514 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method SelectConnection._on_connection_start of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,515 [callback] [DEBUG]  Calling <bound method SelectConnection._on_connection_start of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>> for "0:Connection.Start"
2017-05-31 15:00:52,516 [callback] [DEBUG]  Added: {'callback': <bound method SelectConnection._on_connection_tune of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,520 [callback] [DEBUG]  Processing 0:Connection.Tune
2017-05-31 15:00:52,521 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,521 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,522 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method SelectConnection._on_connection_tune of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,523 [callback] [DEBUG]  Calling <bound method SelectConnection._on_connection_tune of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>> for "0:Connection.Tune"
2017-05-31 15:00:52,524 [connection] [DEBUG]  Creating a HeartbeatChecker: 580
2017-05-31 15:00:52,538 [callback] [DEBUG]  Added: {'callback': <bound method SelectConnection._on_connection_open of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,560 [callback] [DEBUG]  Processing 0:Connection.OpenOk
2017-05-31 15:00:52,561 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,561 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,562 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method SelectConnection._on_connection_open of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,563 [callback] [DEBUG]  Calling <bound method SelectConnection._on_connection_open of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>> for "0:Connection.OpenOk"
2017-05-31 15:00:52,563 [callback] [DEBUG]  Added: {'callback': <bound method SelectConnection._on_connection_closed of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,564 [callback] [DEBUG]  Processing 0:_on_connection_open
2017-05-31 15:00:52,564 [callback] [DEBUG]  Calling <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551f1e8>> for "0:_on_connection_open"
2017-05-31 15:00:52,565 [connection] [DEBUG]  Creating channel 1
2017-05-31 15:00:52,565 [callback] [DEBUG]  Added: {'callback': <bound method SelectConnection._on_channel_cleanup of <pika.adapters.select_connection.SelectConnection object at 0x7551e3d0>>, 'only': <pika.channel.Channel object at 0x76c35730>, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,566 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_getempty of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,567 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_cancel of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,568 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_flow of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,568 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_close of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,569 [channel] [DEBUG]  Adding in on_synchronous_complete callback
2017-05-31 15:00:52,569 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,570 [channel] [DEBUG]  Adding passed in callback
2017-05-31 15:00:52,570 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_openok of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,573 [callback] [DEBUG]  Added: {'callback': <bound method BlockingChannel._on_consumer_cancelled_by_broker of <pika.adapters.blocking_connection.BlockingChannel object at 0x7551e510>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,574 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.signal_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fb70>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,575 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551faa8>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,576 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fb48>>, 'only': None, 'one_shot': False, 'arguments': None}
2017-05-31 15:00:52,577 [blocking_connection] [INFO ]  Created channel=1
2017-05-31 15:00:52,578 [callback] [DEBUG]  Processing 1:Channel.OpenOk
2017-05-31 15:00:52,579 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,579 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,581 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,581 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,582 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,582 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method Channel._on_openok of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,583 [callback] [DEBUG]  Calling <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>> for "1:Channel.OpenOk"
2017-05-31 15:00:52,583 [channel] [DEBUG]  0 blocked frames
2017-05-31 15:00:52,583 [callback] [DEBUG]  Calling <bound method Channel._on_openok of <pika.channel.Channel object at 0x76c35730>> for "1:Channel.OpenOk"
2017-05-31 15:00:52,584 [channel] [DEBUG]  Adding in on_synchronous_complete callback
2017-05-31 15:00:52,584 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,585 [channel] [DEBUG]  Adding passed in callback
2017-05-31 15:00:52,585 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,587 [callback] [DEBUG]  Processing 1:Exchange.DeclareOk
2017-05-31 15:00:52,587 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,588 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,588 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,589 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,589 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,589 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,590 [callback] [DEBUG]  Calling <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>> for "1:Exchange.DeclareOk"
2017-05-31 15:00:52,591 [channel] [DEBUG]  0 blocked frames
2017-05-31 15:00:52,592 [callback] [DEBUG]  Calling <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>> for "1:Exchange.DeclareOk"
2017-05-31 15:00:52,593 [channel] [DEBUG]  Adding in on_synchronous_complete callback
2017-05-31 15:00:52,594 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': {'queue': 'airtime-uploads'}, 'calls': 1}
2017-05-31 15:00:52,594 [channel] [DEBUG]  Adding passed in callback
2017-05-31 15:00:52,595 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>>, 'only': None, 'one_shot': True, 'arguments': {'queue': 'airtime-uploads'}, 'calls': 1}
2017-05-31 15:00:52,598 [callback] [DEBUG]  Processing 1:Queue.DeclareOk
2017-05-31 15:00:52,598 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,599 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,600 [callback] [DEBUG]  Comparing {'queue': 'airtime-uploads'} to {'queue': 'airtime-uploads'}
2017-05-31 15:00:52,600 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': {'queue': 'airtime-uploads'}, 'calls': 0}
2017-05-31 15:00:52,601 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,601 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,601 [callback] [DEBUG]  Comparing {'queue': 'airtime-uploads'} to {'queue': 'airtime-uploads'}
2017-05-31 15:00:52,602 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>>, 'only': None, 'one_shot': True, 'arguments': {'queue': 'airtime-uploads'}, 'calls': 0}
2017-05-31 15:00:52,602 [callback] [DEBUG]  Calling <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>> for "1:Queue.DeclareOk"
2017-05-31 15:00:52,602 [channel] [DEBUG]  0 blocked frames
2017-05-31 15:00:52,603 [callback] [DEBUG]  Calling <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>> for "1:Queue.DeclareOk"
2017-05-31 15:00:52,603 [channel] [DEBUG]  Adding in on_synchronous_complete callback
2017-05-31 15:00:52,604 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,604 [channel] [DEBUG]  Adding passed in callback
2017-05-31 15:00:52,605 [callback] [DEBUG]  Added: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 1}
2017-05-31 15:00:52,608 [callback] [DEBUG]  Processing 1:Queue.BindOk
2017-05-31 15:00:52,608 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,609 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,609 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,610 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,610 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,611 [callback] [DEBUG]  Removing callback #0: {'callback': <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>>, 'only': None, 'one_shot': True, 'arguments': None, 'calls': 0}
2017-05-31 15:00:52,611 [callback] [DEBUG]  Calling <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>> for "1:Queue.BindOk"
2017-05-31 15:00:52,611 [channel] [DEBUG]  0 blocked frames
2017-05-31 15:00:52,612 [callback] [DEBUG]  Calling <bound method _CallbackResult.set_value_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fd00>> for "1:Queue.BindOk"
2017-05-31 15:00:52,612 [message_listener] [INFO ]   Listening for messages...
2017-05-31 15:00:52,614 [channel] [DEBUG]  Adding in on_synchronous_complete callback
2017-05-31 15:00:52,615 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': {'consumer_tag': 'ctag1.b3345579c67e40449e814d619e214848'}, 'calls': 1}
2017-05-31 15:00:52,615 [channel] [DEBUG]  Adding passed in callback
2017-05-31 15:00:52,616 [callback] [DEBUG]  Added: {'callback': <bound method Channel._on_eventok of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': {'consumer_tag': 'ctag1.b3345579c67e40449e814d619e214848'}, 'calls': 1}
2017-05-31 15:00:52,619 [callback] [DEBUG]  Processing 1:Basic.ConsumeOk
2017-05-31 15:00:52,620 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,621 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,621 [callback] [DEBUG]  Comparing {'consumer_tag': 'ctag1.b3345579c67e40449e814d619e214848'} to {'consumer_tag': 'ctag1.b3345579c67e40449e814d619e214848'}
2017-05-31 15:00:52,622 [callback] [DEBUG]  Removing callback #1: {'callback': <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': {'consumer_tag': 'ctag1.b3345579c67e40449e814d619e214848'}, 'calls': 0}
2017-05-31 15:00:52,623 [callback] [DEBUG]  Processing use of oneshot callback
2017-05-31 15:00:52,623 [callback] [DEBUG]  0 registered uses left
2017-05-31 15:00:52,624 [callback] [DEBUG]  Comparing {'consumer_tag': 'ctag1.b3345579c67e40449e814d619e214848'} to {'consumer_tag': 'ctag1.b3345579c67e40449e814d619e214848'}
2017-05-31 15:00:52,624 [callback] [DEBUG]  Removing callback #1: {'callback': <bound method Channel._on_eventok of <pika.channel.Channel object at 0x76c35730>>, 'only': None, 'one_shot': True, 'arguments': {'consumer_tag': 'ctag1.b3345579c67e40449e814d619e214848'}, 'calls': 0}
2017-05-31 15:00:52,625 [callback] [DEBUG]  Calling <bound method _CallbackResult.signal_once of <pika.adapters.blocking_connection._CallbackResult object at 0x7551fb70>> for "1:Basic.ConsumeOk"
2017-05-31 15:00:52,625 [callback] [DEBUG]  Calling <bound method Channel._on_synchronous_complete of <pika.channel.Channel object at 0x76c35730>> for "1:Basic.ConsumeOk"
2017-05-31 15:00:52,625 [channel] [DEBUG]  0 blocked frames
2017-05-31 15:00:52,626 [callback] [DEBUG]  Calling <bound method Channel._on_eventok of <pika.channel.Channel object at 0x76c35730>> for "1:Basic.ConsumeOk"
2017-05-31 15:00:52,626 [channel] [DEBUG]  Discarding frame <METHOD(['channel_number=1', 'frame_type=1', "method=<Basic.ConsumeOk(['consumer_tag=ctag1.b3345579c67e40449e814d619e214848'])>"])>
2017-05-31 15:01:11,389 [message_listener] [INFO ]   - Received '{"tmp_file_path":"\/srv\/airtime\/stor\/organize\/Killing_Joke_-_Red.mp3","storage_backend":"file","import_directory":"\/srv\/airtime\/stor\/\/imported\/1","original_filename":"Killing_Joke_-_Red.mp3","callback_url":"http:\/\/localhost\/\/rest\/media\/4","api_key":"GU3LONLJ4TZBBA5ZC3OV","file_prefix":""}' on routing_key ''
2017-05-31 15:01:11,417 [analyzer_pipeline] [ERROR]  'module' object has no attribute 'from_file'
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/airtime_analyzer-0.1-py2.7.egg/airtime_analyzer/analyzer_pipeline.py", line 70, in run_analysis
    metadata = MetadataAnalyzer.analyze(audio_file_path, metadata)
  File "/usr/local/lib/python2.7/dist-packages/airtime_analyzer-0.1-py2.7.egg/airtime_analyzer/metadata_analyzer.py", line 44, in analyze
    mime_check = magic.from_file(filename, mime=True)
AttributeError: 'module' object has no attribute 'from_file'
2017-05-31 15:01:11,420 [message_listener] [ERROR]  Analyzer pipeline exception: 'module' object has no attribute 'from_file'
2017-05-31 15:01:11,452 [connectionpool] [DEBUG]  Starting new HTTP connection (1): localhost
2017-05-31 15:01:11,876 [connectionpool] [DEBUG]  http://localhost:80 "PUT //rest/media/4 HTTP/1.1" 201 1255
2017-05-31 15:01:11,882 [status_reporter] [INFO ]  HTTP request sent successfully.
2017-05-31 15:03:04,248 [message_listener] [INFO ]   - Received '{"tmp_file_path":"\/srv\/airtime\/stor\/organize\/Killing_Joke_-_Red.mp3","storage_backend":"file","import_directory":"\/srv\/airtime\/stor\/\/imported\/1","original_filename":"Killing_Joke_-_Red.mp3","callback_url":"http:\/\/localhost\/\/rest\/media\/5","api_key":"GU3LONLJ4TZBBA5ZC3OV","file_prefix":""}' on routing_key ''
2017-05-31 15:03:04,278 [analyzer_pipeline] [ERROR]  'module' object has no attribute 'from_file'
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/airtime_analyzer-0.1-py2.7.egg/airtime_analyzer/analyzer_pipeline.py", line 70, in run_analysis
    metadata = MetadataAnalyzer.analyze(audio_file_path, metadata)
  File "/usr/local/lib/python2.7/dist-packages/airtime_analyzer-0.1-py2.7.egg/airtime_analyzer/metadata_analyzer.py", line 44, in analyze
    mime_check = magic.from_file(filename, mime=True)
AttributeError: 'module' object has no attribute 'from_file'
2017-05-31 15:03:04,280 [message_listener] [ERROR]  Analyzer pipeline exception: 'module' object has no attribute 'from_file'
2017-05-31 15:03:04,328 [connectionpool] [DEBUG]  Starting new HTTP connection (1): localhost
2017-05-31 15:03:04,711 [connectionpool] [DEBUG]  http://localhost:80 "PUT //rest/media/5 HTTP/1.1" 201 1255
2017-05-31 15:03:04,715 [status_reporter] [INFO ]  HTTP request sent successfully.
aresstokrat picture aresstokrat on 31 May 2017

But i dont see that liquidsoap is dawn at the admin panel for now (15 minutes passed).
Only pypo is marked as down there.

But in the stream section i see:

clicked "Custom / 3rd Party Streaming" radiobutton, and entered parameters of icecast2. Saved.

Can not connect to the streaming server
could not write data to host: Connection refused in write()
aresstokrat picture aresstokrat on 31 May 2017

Honestly at this point, Debian Jessie has been tested the least. If you just want to get started I'd recommend Ubuntu 14.04. I see that you are running this on a raspberrypi based upon the hostname. This also hasn't been tested as far as I know so there may be an issue with some of the ARM binaries.

Hmm this does seem to be an issue with the mime magic. I know that we recently did a commit on this - mime_check = magic.from_file(filename, mime=True) might this be related to #169 ?

Robbt picture Robbt on 31 May 2017

I actually had a working vagrant setup on jessie a couple of weeks ago.

The pyponotify and liquidsoap errors indicators that airtime-playout is not doing its job. It should generate a /etc/airtime/liquidsoap.cfg based on info from the api/config.

Does the following tell you anything? I think this is the bit that doesn't have proper logging to a file :(

systemctl stop airtime-playout
sudo -u www-data airtime-playout
hairmare picture hairmare on 31 May 2017

checked status page, all this marked as dawn again:

Media Analzyer
Pypo
Liquidsoap
aresstokrat picture aresstokrat on 31 May 2017

after hints made from #212
liquidsoap.cfg is changing to the settings set uped in admin panel !

but service still getting down and stream page gives

Can not connect to the streaming server
could not write data to host: Connection refused in write()
aresstokrat picture aresstokrat on 31 May 2017

Good to hear that the liquidsoap config is now updating. Has anything changed in /var/log/airtime/pypo-liquidsoap/ls_script.log? Can you post the output of sudo -u www-data airtime-playout if any.

hairmare picture hairmare on 31 May 2017

sure, here we go:

sudo tail /var/log/airtime/pypo-liquidsoap/ls_script.log

2017/05/31 18:06:52 [_a:3] Connecting mount _a for source@localhost...
2017/05/31 18:06:58 [_a:2] Connection failed: could not write data to host: Connection refused in write()
2017/05/31 18:07:21 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496242068.24 &
2017/05/31 18:07:27 [_a:3] Will try again in 5.00 sec.
2017/05/31 18:07:50 [clock.wallclock_main:2] Too much latency! Resetting active sources...
2017/05/31 18:08:07 [_a:3] Connecting mount _a for source@localhost...
2017/05/31 18:08:54 [_a:2] Connection failed: could not write data to host: Connection refused in write()
2017/05/31 18:58:03 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496242068.24 &
2017/05/31 19:07:04 [server:3] New client: localhost.
2017/05/31 19:07:03 [_a:3] Will try again in 5.00 sec.

sudo -u www-data airtime-playout

2017-06-01 10:20:44,326 [__main__] [INFO ]  New locale set to: ru_RU.UTF-8
2017-06-01 10:20:44,333 [__main__] [INFO ]  ###########################################
2017-06-01 10:20:44,334 [__main__] [INFO ]  #             *** pypo  ***               #
2017-06-01 10:20:44,334 [__main__] [INFO ]  #   Liquidsoap Scheduled Playout System   #
2017-06-01 10:20:44,334 [__main__] [INFO ]  ###########################################
2017-06-01 10:20:44,335 [__main__] [INFO ]  Timezone: ('+03', '+03')
2017-06-01 10:20:44,335 [__main__] [INFO ]  UTC time: 2017-06-01 07:20:44.335281
2017-06-01 10:20:44,592 [api_client] [INFO ]  Airtime API version found: 1.1
2017-06-01 10:20:44,592 [api_client] [INFO ]  pypo is only compatible with API version: 1.1
2017-06-01 10:20:44,775 [__main__] [ERROR]  [Errno 111] Π’ соСдинСнии ΠΎΡ‚ΠΊΠ°Π·Π°Π½ΠΎ
2017-06-01 10:20:44,777 [__main__] [WARNI]  Liquidsoap doesn't appear to be running!, Sleeping and trying again
2017-06-01 10:20:45,781 [__main__] [ERROR]  [Errno 111] Π’ соСдинСнии ΠΎΡ‚ΠΊΠ°Π·Π°Π½ΠΎ
2017-06-01 10:20:45,784 [__main__] [WARNI]  Liquidsoap doesn't appear to be running!, Sleeping and trying again
aresstokrat picture aresstokrat on 1 Jun 2017

all 3 services down

aresstokrat picture aresstokrat on 1 Jun 2017

managed to run stream!
service is up in the "Status" page of the admin panel when show is runing, and marked "down" when no show is runing at the moment.

when reconfigure the stream have to restart service manualy

aresstokrat picture aresstokrat on 1 Jun 2017

service is up in the "Status" page of the admin panel when show is runing, and marked "down" when no show is runing at the moment.

I'm not sure why it would do that. The liquidsoap service should always run and just send silence to the stream server if nothing is programmed.

when reconfigure the stream have to restart service manualy

The system V init won't restart processes if they exit (but upstart or systemd will). This will be fixed once we get #173 done and systemd units are installed on Jessie. If you would like to try out the unit files you can install them manually.

unit_src_dir="/vagrant/installer/systemd" # replace with path to same folder in git clone or downloaded tarball
unit_dir="/etc/systemd/system"

# copy files to destination
cp -rp ${unit_src_dir}/*.service ${unit_dir}

# Rewrite files all files except celery to use apache user "www-data"
# the users in the files are "wrong" since the users in them are in the centos rpm install
for service in `ls ${unit_src_dir}/*.service`; do
    unit_name=`basename ${service}`
    if [ "$unit_name" = "airtime-celery.service" ]; then
        # celery has it's own system user "celery"
        continue
    fi
    sed -i \
        -e 's/User=.*/User=www-data/' \
        -e 's/Group=.*/Group=www-data/' \
        ${unit_dir}/${unit_name}
done

# reload systemd units
systemctl daemon-reload

You might need to fix the actual path to the various binaries in the unit files (on ExecStart= lines) before running systemctl daemon-reload. I'm not sure if they point to where everything gets installed on Jessie.

hairmare picture hairmare on 1 Jun 2017

I'm sorry im very new to linux. I will go step by step. Correct me if im wrong.

  1. Disable all 'airtime-*' services via 'sudo update-rc.d airtime-NameOfService disable'
  2. Make 'sh' script file with content you gave me above + correct the paths in 'unit_src_dir' to git clone archive + duplicate all lines from block
    ' if [ "$unit_name" = "airtime-celery.service" ]; then'
    pasting the name of services one by one.
/home/pi/libretime-git/libretime/installer/systemd/airtime_analyzer.service
/home/pi/libretime-git/libretime/installer/systemd/airtime-celery.service
/home/pi/libretime-git/libretime/installer/systemd/airtime-liquidsoap.service
/home/pi/libretime-git/libretime/installer/systemd/airtime-playout.service
  1. Correct paths in services to bins (ExecStart=)
  2. Run .sh from sudo user.

Right?

aresstokrat picture aresstokrat on 2 Jun 2017

You can use systemctl disable <service> instead of update-rc.d but the latter should work just as well. You will certainly have to use systemctl enable <service> after installing the new service files.

Apart from that your steps look absolutely ok. If the script looks daunting you can also just copy the files to /etc/systemd/system manually and then edit their ExecStart= lines and make sure that they contain User=www-data and Group=www-data (except celery which has User=celery, ...).

hairmare picture hairmare on 2 Jun 2017
👍1

i made all the changes, all gone just fine!

For now services is UP and working normal. In admin panel they also marked as normal.
Stream is marked as
"Can not connect to the streaming server
could not write data to host: Connection refused in write()"
and "ON AIR" is glowing RED.

I checked all services files, evr. is good inside, user and groups are www-data except celery service.

In the Status page of icecast there is no mounting point. And i cant connect to the stream via player.

2017/06/05 15:17:20 [mp3-128:3] Connecting mount mp3-128 for source@localhost...
2017/06/05 15:17:20 [mp3-128:2] Connection failed: could not write data to host: Connection refused in write()
2017/06/05 15:17:20 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496662672.62 &
2017/06/05 15:17:20 [mp3-128:3] Will try again in 5.00 sec.

2017-06-05 15:18:43,505 [recorder] [INFO ]  Parsing recording show schedules...
2017-06-05 15:18:43,506 [recorder] [INFO ]  Bootstrap recorder schedule received: {u'is_recording': False, u'server_timezone': u'Europe/Moscow', u'shows': []}
2017-06-05 15:18:43,506 [recorder] [INFO ]  Bootstrap complete: got initial copy of the schedule
2017-06-05 15:18:43,822 [pypoliquidsoap] [INFO ]  Need to add items to Liquidsoap *now*: set([113])
2017-06-05 15:18:43,823 [pypofetch] [INFO ]  Bootstrap schedule received: {u'media': {u'2017-06-05-12-17-38': {u'cue_out': 375.223, u'independent_event': False, u'end': datetime.datetime(2017, 6, 5, 12, 23, 53), u'fade_out': 500, u'show_name': u'Untitled Show', 'file_ready': True, u'uri': u'http://localhost//rest/media/142', u'cue_in': 65.832843, u'start': datetime.datetime(2017, 6, 5, 12, 17, 38), u'replay_gain': -4.77, 'dst': u'/var/tmp/airtime/pypo/cache/scheduler/142.mp3', u'filesize': 11876319, 'file_ext': '.mp3', u'row_id': 113, u'metadata': {u'rating': None, u'soundcloud_upload_time': None, u'report_datetime': None, u'lyrics': None, u'soundcloud_error_code': None, u'year': u'2015', u'channels': 2, u'bit_rate': 253193, u'buy_this_url': None, u'original_artist': None, u'composer': None, u'mtime': u'2017-06-05 10:40:38', u'contributor': None, u'editedby': None, u'id': 142, u'subject': None, u'radio_station_name': None, u'mood': None, u'copyright': None, u'filepath': u'imported/1/Infected Mushroom/Converting Vegetarians II/Infected_Mushroom_-_Animatronica.mp3', u'soundcloud_id': None, u'description': None, u'catalog_number': None, u'orchestra': None, u'comments': None, u'label': None, u'disc_number': None, u'ftype': u'audioclip', u'filesize': 11876319, u'cueout': u'00:06:15.222834', u'encoded_by': None, u'currentlyaccessing': 0, u'md5': u'98efcad74459d917f889edf733b9687f', u'soundcloud_error_msg': None, u'track_title': u'Animatronica', u'info_url': None, u'lyricist': None, u'import_status': 0, u'conductor': None, u'format': None, u'radio_station_url': None, u'artist_name': u'Infected Mushroom', u'encoder': None, u'audio_source_url': None, u'original_lyricist': None, u'mime': u'audio/mp3', u'cuein': u'00:00:00.008912', u'album_title': u'Converting Vegetarians II', u'genre': u'Electronica', u'hidden': False, u'utime': u'2017-06-05 09:04:10', u'report_organization': None, u'name': u'', u'language': None, u'report_location': None, u'url': None, u'checksum': None, u'bpm': None, u'track_number': 4, u'isrc_number': None, u'length': u'00:06:15.173333', u'sample_rate': 44100, u'artist_url': None, u'soundcloud_link_to_file': None, u'directory': 1, u'lptime': u'2017-06-05 12:17:41', u'replay_gain': u'-4.77', u'owner_id': 1}, u'type': u'file', u'id': 142, u'fade_in': 500}, u'2017-06-05-13-09-00': {u'start': datetime.datetime(2017, 6, 5, 13, 9), u'independent_event': True, u'end': datetime.datetime(2017, 6, 5, 13, 9), u'event_type': u'kick_out', u'type': u'event'}}}
2017-06-05 15:18:43,825 [pypofetch] [INFO ]  Loop #1
2017-06-05 15:18:43,947 [pypopush] [INFO ]  heartbeat
2017-06-05 15:18:43,948 [pypoliqqueue] [INFO ]  New schedule received: {u'2017-06-05-13-09-00': {u'start': datetime.datetime(2017, 6, 5, 13, 9), u'independent_event': True, u'end': datetime.datetime(2017, 6, 5, 13, 9), u'event_type': u'kick_out', u'type': u'event'}}
2017-06-05 15:18:43,949 [pypoliqqueue] [INFO ]  waiting 3016.051084s until next scheduled item
aresstokrat picture aresstokrat on 5 Jun 2017

pi@raspberrypi:/etc/systemd/system $ sudo -u www-data airtime-playout

2017-06-05 16:46:06,572 [__main__] [INFO ]  New locale set to: ru_RU.UTF-8
2017-06-05 16:46:06,579 [__main__] [INFO ]  ###########################################
2017-06-05 16:46:06,579 [__main__] [INFO ]  #             *** pypo  ***               #
2017-06-05 16:46:06,580 [__main__] [INFO ]  #   Liquidsoap Scheduled Playout System   #
2017-06-05 16:46:06,580 [__main__] [INFO ]  ###########################################
2017-06-05 16:46:06,580 [__main__] [INFO ]  Timezone: ('+03', '+03')
2017-06-05 16:46:06,581 [__main__] [INFO ]  UTC time: 2017-06-05 13:46:06.581035
2017-06-05 16:46:06,809 [api_client] [INFO ]  Airtime API version found: 1.1
2017-06-05 16:46:06,810 [api_client] [INFO ]  pypo is only compatible with API version: 1.1
2017-06-05 16:46:07,019 [__main__] [INFO ]  Liquidsoap version string found 1.1.1
2017-06-05 16:46:07,020 [pypomessagehandler] [INFO ]  Initializing RabbitMQ stuff
2017-06-05 16:46:07,114 [pypofetch] [INFO ]  PypoFetch: init complete
2017-06-05 16:46:07,127 [pypoliqqueue] [INFO ]  waiting indefinitely for schedule
2017-06-05 16:46:07,145 [recorder] [INFO ]  RecorderFetch: init complete
2017-06-05 16:46:07,378 [recorder] [INFO ]  Started...
2017-06-05 16:46:07,441 [telnetliquidsoap] [INFO ]  streams.scheduled_play_start

2017-06-05 16:46:07,442 [telnetliquidsoap] [INFO ]  streams.live_dj_stop

2017-06-05 16:46:07,443 [telnetliquidsoap] [INFO ]  streams.master_dj_stop

2017-06-05 16:46:07,445 [telnetliquidsoap] [INFO ]  vars.stream_metadata_type 0

2017-06-05 16:46:07,445 [telnetliquidsoap] [INFO ]  vars.station_name firefm

2017-06-05 16:46:07,446 [telnetliquidsoap] [INFO ]  vars.default_dj_fade 0.000

2017-06-05 16:46:07,644 [recorder] [INFO ]  Parsing recording show schedules...
2017-06-05 16:46:07,645 [recorder] [INFO ]  Bootstrap recorder schedule received: {u'is_recording': False, u'server_timezone': u'Europe/Moscow', u'shows': []}
2017-06-05 16:46:07,645 [recorder] [INFO ]  Bootstrap complete: got initial copy of the schedule
2017-06-05 16:46:07,950 [pypofetch] [INFO ]  Bootstrap schedule received: {u'media': {}}
2017-06-05 16:46:07,951 [pypofetch] [INFO ]  Loop #1
2017-06-05 16:46:07,959 [pypopush] [INFO ]  heartbeat
2017-06-05 16:46:07,960 [pypoliqqueue] [INFO ]  New schedule received: {}
2017-06-05 16:46:07,960 [pypoliqqueue] [INFO ]  waiting indefinitely for schedule
2017-06-05 16:46:32,551 [pypomessagehandler] [INFO ]  Received event from RabbitMQ: {"schedule":{"media":{"2017-06-05-14-46-00":{"start":"2017-06-05-14-46-00","end":"2017-06-05-14-46-00","event_type":"kick_out","type":"event","independent_event":true}}},"event_type":"update_schedule"}
2017-06-05 16:46:32,552 [pypomessagehandler] [INFO ]  Handling command: update_schedule
2017-06-05 16:46:32,552 [pypomessagehandler] [INFO ]  Updating schdule...
2017-06-05 16:46:32,562 [pypofetch] [INFO ]  Received event from Pypo Message Handler: {"schedule":{"media":{"2017-06-05-14-46-00":{"start":"2017-06-05-14-46-00","end":"2017-06-05-14-46-00","event_type":"kick_out","type":"event","independent_event":true}}},"event_type":"update_schedule"}
2017-06-05 16:46:32,563 [pypofetch] [INFO ]  Handling command: update_schedule
2017-06-05 16:46:32,595 [pypofetch] [INFO ]  New timeout: 480
2017-06-05 16:46:32,595 [pypofetch] [INFO ]  Loop #2
2017-06-05 16:46:32,631 [pypoliqqueue] [INFO ]  New schedule received: {u'2017-06-05-14-46-00': {u'start': datetime.datetime(2017, 6, 5, 14, 46), u'independent_event': True, u'end': datetime.datetime(2017, 6, 5, 14, 46), u'event_type': u'kick_out', u'type': u'event'}}
2017-06-05 16:46:32,632 [pypoliqqueue] [INFO ]  waiting 3567.367558s until next scheduled item
2017-06-05 16:46:45,655 [pypomessagehandler] [INFO ]  Received event from RabbitMQ: {"schedule":{"media":{"2017-06-05-14-46-00":{"start":"2017-06-05-14-46-00","end":"2017-06-05-14-46-00","event_type":"kick_out","type":"event","independent_event":true},"2017-06-05-13-46-44":{"id":144,"type":"file","metadata":{"id":144,"name":"","mime":"audio\/mp3","ftype":"audioclip","directory":1,"filepath":"imported\/1\/Arcade Fire\/Reflektor\/Arcade_Fire_-_You_Already_Know.mp3","import_status":0,"currentlyaccessing":0,"editedby":null,"mtime":"2017-06-05 10:42:36","utime":"2017-06-05 10:42:15","lptime":"2017-06-05 12:50:49","md5":"41a32b0f6563b9e071f0c2bc69248a19","track_title":"You Already Know","artist_name":"Arcade Fire","bit_rate":320112,"sample_rate":44100,"format":null,"length":"00:03:59.066667","album_title":"Reflektor","genre":null,"comments":null,"year":"2013","track_number":6,"channels":2,"url":null,"bpm":null,"rating":null,"encoded_by":null,"disc_number":null,"mood":null,"label":null,"composer":null,"encoder":null,"checksum":null,"lyrics":null,"orchestra":null,"conductor":null,"lyricist":null,"original_lyricist":null,"radio_station_name":null,"info_url":null,"artist_url":null,"audio_source_url":null,"radio_station_url":null,"buy_this_url":null,"isrc_number":null,"catalog_number":null,"original_artist":null,"copyright":null,"report_datetime":null,"report_location":null,"report_organization":null,"subject":null,"contributor":null,"language":null,"soundcloud_id":null,"soundcloud_error_code":null,"soundcloud_error_msg":null,"soundcloud_link_to_file":null,"soundcloud_upload_time":null,"replay_gain":"-9.46","owner_id":1,"cuein":"00:00:00.369728","cueout":"00:03:59.124898","hidden":false,"filesize":9568427,"description":null},"row_id":128,"uri":"http:\/\/localhost\/\/rest\/media\/144","fade_in":500,"fade_out":500,"cue_in":0.37,"cue_out":239.125,"start":"2017-06-05-13-46-44","end":"2017-06-05-13-50-42","show_name":"Untitled Show","replay_gain":-9.46,"independent_event":false,"filesize":9568427},"2017-06-05-13-50-42":{"id":145,"type":"file","metadata":{"id":145,"name":"","mime":"audio\/mp3","ftype":"audioclip","directory":1,"filepath":"imported\/1\/Arcade Fire\/Reflektor\/Arcade_Fire_-_Joan_of_Arc.mp3","import_status":0,"currentlyaccessing":0,"editedby":null,"mtime":"2017-06-05 12:25:33","utime":"2017-06-05 12:25:02","lptime":"2017-06-05 12:54:48","md5":"936da99172c12427328650345e2e7975","track_title":"Joan of Arc","artist_name":"Arcade Fire","bit_rate":320087,"sample_rate":44100,"format":null,"length":"00:05:26.52","album_title":"Reflektor","genre":null,"comments":null,"year":"2013","track_number":7,"channels":2,"url":null,"bpm":null,"rating":null,"encoded_by":null,"disc_number":null,"mood":null,"label":null,"composer":null,"encoder":null,"checksum":null,"lyrics":null,"orchestra":null,"conductor":null,"lyricist":null,"original_lyricist":null,"radio_station_name":null,"info_url":null,"artist_url":null,"audio_source_url":null,"radio_station_url":null,"buy_this_url":null,"isrc_number":null,"catalog_number":null,"original_artist":null,"copyright":null,"report_datetime":null,"report_location":null,"report_organization":null,"subject":null,"contributor":null,"language":null,"soundcloud_id":null,"soundcloud_error_code":null,"soundcloud_error_msg":null,"soundcloud_link_to_file":null,"soundcloud_upload_time":null,"replay_gain":"-7.24","owner_id":1,"cuein":"00:00:00.136848","cueout":"00:05:24.568027","hidden":false,"filesize":13066735,"description":null},"row_id":129,"uri":"http:\/\/localhost\/\/rest\/media\/145","fade_in":500,"fade_out":500,"cue_in":0.137,"cue_out":324.568,"start":"2017-06-05-13-50-42","end":"2017-06-05-13-56-06","show_name":"Untitled Show","replay_gain":-7.24,"independent_event":false,"filesize":13066735},"2017-06-05-13-56-06":{"id":141,"type":"file","metadata":{"id":141,"name":"","mime":"audio\/mp3","ftype":"audioclip","directory":1,"filepath":"imported\/1\/Benny Smiles\/Hotline Miami 2: Wrong Number\/Benny_Smiles_-_Hotline_Theme.mp3","import_status":0,"currentlyaccessing":0,"editedby":null,"mtime":"2017-06-05 10:40:08","utime":"2017-06-05 09:03:34","lptime":"2017-06-05 13:00:13","md5":"9a39d190be565ce884f5782321d98f71","track_title":"Hotline Theme","artist_name":"Benny Smiles","bit_rate":223512,"sample_rate":44100,"format":null,"length":"00:03:39.378571","album_title":"Hotline Miami 2: Wrong Number","genre":"Soundtrack","comments":null,"year":"2015","track_number":33,"channels":2,"url":null,"bpm":null,"rating":null,"encoded_by":null,"disc_number":null,"mood":null,"label":null,"composer":null,"encoder":null,"checksum":null,"lyrics":null,"orchestra":null,"conductor":null,"lyricist":null,"original_lyricist":null,"radio_station_name":null,"info_url":null,"artist_url":null,"audio_source_url":null,"radio_station_url":null,"buy_this_url":null,"isrc_number":null,"catalog_number":null,"original_artist":null,"copyright":null,"report_datetime":null,"report_location":null,"report_organization":null,"subject":null,"contributor":null,"language":null,"soundcloud_id":null,"soundcloud_error_code":null,"soundcloud_error_msg":null,"soundcloud_link_to_file":null,"soundcloud_upload_time":null,"replay_gain":"-7.01","owner_id":1,"cuein":"00:00:00.026009","cueout":"00:03:36.170748","hidden":false,"filesize":6213674,"description":null},"row_id":130,"uri":"http:\/\/localhost\/\/rest\/media\/141","fade_in":500,"fade_out":500,"cue_in":0.026,"cue_out":216.171,"start":"2017-06-05-13-56-06","end":"2017-06-05-13-59-42","show_name":"Untitled Show","replay_gain":-7.01,"independent_event":false,"filesize":6213674},"2017-06-05-13-59-41":{"id":142,"type":"file","metadata":{"id":142,"name":"","mime":"audio\/mp3","ftype":"audioclip","directory":1,"filepath":"imported\/1\/Infected Mushroom\/Converting Vegetarians II\/Infected_Mushroom_-_Animatronica.mp3","import_status":0,"currentlyaccessing":0,"editedby":null,"mtime":"2017-06-05 10:40:38","utime":"2017-06-05 09:04:10","lptime":"2017-06-05 13:03:47","md5":"98efcad74459d917f889edf733b9687f","track_title":"Animatronica","artist_name":"Infected Mushroom","bit_rate":253193,"sample_rate":44100,"format":null,"length":"00:06:15.173333","album_title":"Converting Vegetarians II","genre":"Electronica","comments":null,"year":"2015","track_number":4,"channels":2,"url":null,"bpm":null,"rating":null,"encoded_by":null,"disc_number":null,"mood":null,"label":null,"composer":null,"encoder":null,"checksum":null,"lyrics":null,"orchestra":null,"conductor":null,"lyricist":null,"original_lyricist":null,"radio_station_name":null,"info_url":null,"artist_url":null,"audio_source_url":null,"radio_station_url":null,"buy_this_url":null,"isrc_number":null,"catalog_number":null,"original_artist":null,"copyright":null,"report_datetime":null,"report_location":null,"report_organization":null,"subject":null,"contributor":null,"language":null,"soundcloud_id":null,"soundcloud_error_code":null,"soundcloud_error_msg":null,"soundcloud_link_to_file":null,"soundcloud_upload_time":null,"replay_gain":"-4.77","owner_id":1,"cuein":"00:00:00.008912","cueout":"00:06:15.222834","hidden":false,"filesize":11876319,"description":null},"row_id":131,"uri":"http:\/\/localhost\/\/rest\/media\/142","fade_in":500,"fade_out":500,"cue_in":0.009,"cue_out":375.223,"start":"2017-06-05-13-59-41","end":"2017-06-05-14-05-57","show_name":"Untitled Show","replay_gain":-4.77,"independent_event":true,"filesize":11876319}}},"event_type":"update_schedule"}
2017-06-05 16:46:45,657 [pypomessagehandler] [INFO ]  Handling command: update_schedule
2017-06-05 16:46:45,659 [pypomessagehandler] [INFO ]  Updating schdule...
2017-06-05 16:46:45,685 [pypofetch] [INFO ]  Received event from Pypo Message Handler: {"schedule":{"media":{"2017-06-05-14-46-00":{"start":"2017-06-05-14-46-00","end":"2017-06-05-14-46-00","event_type":"kick_out","type":"event","independent_event":true},"2017-06-05-13-46-44":{"id":144,"type":"file","metadata":{"id":144,"name":"","mime":"audio\/mp3","ftype":"audioclip","directory":1,"filepath":"imported\/1\/Arcade Fire\/Reflektor\/Arcade_Fire_-_You_Already_Know.mp3","import_status":0,"currentlyaccessing":0,"editedby":null,"mtime":"2017-06-05 10:42:36","utime":"2017-06-05 10:42:15","lptime":"2017-06-05 12:50:49","md5":"41a32b0f6563b9e071f0c2bc69248a19","track_title":"You Already Know","artist_name":"Arcade Fire","bit_rate":320112,"sample_rate":44100,"format":null,"length":"00:03:59.066667","album_title":"Reflektor","genre":null,"comments":null,"year":"2013","track_number":6,"channels":2,"url":null,"bpm":null,"rating":null,"encoded_by":null,"disc_number":null,"mood":null,"label":null,"composer":null,"encoder":null,"checksum":null,"lyrics":null,"orchestra":null,"conductor":null,"lyricist":null,"original_lyricist":null,"radio_station_name":null,"info_url":null,"artist_url":null,"audio_source_url":null,"radio_station_url":null,"buy_this_url":null,"isrc_number":null,"catalog_number":null,"original_artist":null,"copyright":null,"report_datetime":null,"report_location":null,"report_organization":null,"subject":null,"contributor":null,"language":null,"soundcloud_id":null,"soundcloud_error_code":null,"soundcloud_error_msg":null,"soundcloud_link_to_file":null,"soundcloud_upload_time":null,"replay_gain":"-9.46","owner_id":1,"cuein":"00:00:00.369728","cueout":"00:03:59.124898","hidden":false,"filesize":9568427,"description":null},"row_id":128,"uri":"http:\/\/localhost\/\/rest\/media\/144","fade_in":500,"fade_out":500,"cue_in":0.37,"cue_out":239.125,"start":"2017-06-05-13-46-44","end":"2017-06-05-13-50-42","show_name":"Untitled Show","replay_gain":-9.46,"independent_event":false,"filesize":9568427},"2017-06-05-13-50-42":{"id":145,"type":"file","metadata":{"id":145,"name":"","mime":"audio\/mp3","ftype":"audioclip","directory":1,"filepath":"imported\/1\/Arcade Fire\/Reflektor\/Arcade_Fire_-_Joan_of_Arc.mp3","import_status":0,"currentlyaccessing":0,"editedby":null,"mtime":"2017-06-05 12:25:33","utime":"2017-06-05 12:25:02","lptime":"2017-06-05 12:54:48","md5":"936da99172c12427328650345e2e7975","track_title":"Joan of Arc","artist_name":"Arcade Fire","bit_rate":320087,"sample_rate":44100,"format":null,"length":"00:05:26.52","album_title":"Reflektor","genre":null,"comments":null,"year":"2013","track_number":7,"channels":2,"url":null,"bpm":null,"rating":null,"encoded_by":null,"disc_number":null,"mood":null,"label":null,"composer":null,"encoder":null,"checksum":null,"lyrics":null,"orchestra":null,"conductor":null,"lyricist":null,"original_lyricist":null,"radio_station_name":null,"info_url":null,"artist_url":null,"audio_source_url":null,"radio_station_url":null,"buy_this_url":null,"isrc_number":null,"catalog_number":null,"original_artist":null,"copyright":null,"report_datetime":null,"report_location":null,"report_organization":null,"subject":null,"contributor":null,"language":null,"soundcloud_id":null,"soundcloud_error_code":null,"soundcloud_error_msg":null,"soundcloud_link_to_file":null,"soundcloud_upload_time":null,"replay_gain":"-7.24","owner_id":1,"cuein":"00:00:00.136848","cueout":"00:05:24.568027","hidden":false,"filesize":13066735,"description":null},"row_id":129,"uri":"http:\/\/localhost\/\/rest\/media\/145","fade_in":500,"fade_out":500,"cue_in":0.137,"cue_out":324.568,"start":"2017-06-05-13-50-42","end":"2017-06-05-13-56-06","show_name":"Untitled Show","replay_gain":-7.24,"independent_event":false,"filesize":13066735},"2017-06-05-13-56-06":{"id":141,"type":"file","metadata":{"id":141,"name":"","mime":"audio\/mp3","ftype":"audioclip","directory":1,"filepath":"imported\/1\/Benny Smiles\/Hotline Miami 2: Wrong Number\/Benny_Smiles_-_Hotline_Theme.mp3","import_status":0,"currentlyaccessing":0,"editedby":null,"mtime":"2017-06-05 10:40:08","utime":"2017-06-05 09:03:34","lptime":"2017-06-05 13:00:13","md5":"9a39d190be565ce884f5782321d98f71","track_title":"Hotline Theme","artist_name":"Benny Smiles","bit_rate":223512,"sample_rate":44100,"format":null,"length":"00:03:39.378571","album_title":"Hotline Miami 2: Wrong Number","genre":"Soundtrack","comments":null,"year":"2015","track_number":33,"channels":2,"url":null,"bpm":null,"rating":null,"encoded_by":null,"disc_number":null,"mood":null,"label":null,"composer":null,"encoder":null,"checksum":null,"lyrics":null,"orchestra":null,"conductor":null,"lyricist":null,"original_lyricist":null,"radio_station_name":null,"info_url":null,"artist_url":null,"audio_source_url":null,"radio_station_url":null,"buy_this_url":null,"isrc_number":null,"catalog_number":null,"original_artist":null,"copyright":null,"report_datetime":null,"report_location":null,"report_organization":null,"subject":null,"contributor":null,"language":null,"soundcloud_id":null,"soundcloud_error_code":null,"soundcloud_error_msg":null,"soundcloud_link_to_file":null,"soundcloud_upload_time":null,"replay_gain":"-7.01","owner_id":1,"cuein":"00:00:00.026009","cueout":"00:03:36.170748","hidden":false,"filesize":6213674,"description":null},"row_id":130,"uri":"http:\/\/localhost\/\/rest\/media\/141","fade_in":500,"fade_out":500,"cue_in":0.026,"cue_out":216.171,"start":"2017-06-05-13-56-06","end":"2017-06-05-13-59-42","show_name":"Untitled Show","replay_gain":-7.01,"independent_event":false,"filesize":6213674},"2017-06-05-13-59-41":{"id":142,"type":"file","metadata":{"id":142,"name":"","mime":"audio\/mp3","ftype":"audioclip","directory":1,"filepath":"imported\/1\/Infected Mushroom\/Converting Vegetarians II\/Infected_Mushroom_-_Animatronica.mp3","import_status":0,"currentlyaccessing":0,"editedby":null,"mtime":"2017-06-05 10:40:38","utime":"2017-06-05 09:04:10","lptime":"2017-06-05 13:03:47","md5":"98efcad74459d917f889edf733b9687f","track_title":"Animatronica","artist_name":"Infected Mushroom","bit_rate":253193,"sample_rate":44100,"format":null,"length":"00:06:15.173333","album_title":"Converting Vegetarians II","genre":"Electronica","comments":null,"year":"2015","track_number":4,"channels":2,"url":null,"bpm":null,"rating":null,"encoded_by":null,"disc_number":null,"mood":null,"label":null,"composer":null,"encoder":null,"checksum":null,"lyrics":null,"orchestra":null,"conductor":null,"lyricist":null,"original_lyricist":null,"radio_station_name":null,"info_url":null,"artist_url":null,"audio_source_url":null,"radio_station_url":null,"buy_this_url":null,"isrc_number":null,"catalog_number":null,"original_artist":null,"copyright":null,"report_datetime":null,"report_location":null,"report_organization":null,"subject":null,"contributor":null,"language":null,"soundcloud_id":null,"soundcloud_error_code":null,"soundcloud_error_msg":null,"soundcloud_link_to_file":null,"soundcloud_upload_time":null,"replay_gain":"-4.77","owner_id":1,"cuein":"00:00:00.008912","cueout":"00:06:15.222834","hidden":false,"filesize":11876319,"description":null},"row_id":131,"uri":"http:\/\/localhost\/\/rest\/media\/142","fade_in":500,"fade_out":500,"cue_in":0.009,"cue_out":375.223,"start":"2017-06-05-13-59-41","end":"2017-06-05-14-05-57","show_name":"Untitled Show","replay_gain":-4.77,"independent_event":true,"filesize":11876319}}},"event_type":"update_schedule"}
2017-06-05 16:46:45,688 [pypofetch] [INFO ]  Handling command: update_schedule
2017-06-05 16:46:45,708 [pypofile] [INFO ]  copying from http://localhost//rest/media/144 to local cache /var/tmp/airtime/pypo/cache/scheduler/144.mp3
2017-06-05 16:46:45,709 [pypofile] [ERROR]  http://localhost:80/rest/media/144/download
2017-06-05 16:46:45,724 [pypoliquidsoap] [INFO ]  Need to add items to Liquidsoap *now*: set([128])
2017-06-05 16:46:45,727 [pypofetch] [INFO ]  New timeout: 480
2017-06-05 16:46:45,729 [pypofetch] [INFO ]  Loop #3
2017-06-05 16:46:47,571 [pypofile] [INFO ]  copying from http://localhost//rest/media/145 to local cache /var/tmp/airtime/pypo/cache/scheduler/145.mp3
2017-06-05 16:46:47,571 [pypofile] [ERROR]  http://localhost:80/rest/media/145/download
2017-06-05 16:46:47,827 [pypoliqqueue] [INFO ]  New schedule received: {u'2017-06-05-14-46-00': {u'start': datetime.datetime(2017, 6, 5, 14, 46), u'independent_event': True, u'end': datetime.datetime(2017, 6, 5, 14, 46), u'event_type': u'kick_out', u'type': u'event'}, u'2017-06-05-13-59-41': {u'cue_out': 375.223, u'independent_event': True, u'end': datetime.datetime(2017, 6, 5, 14, 5, 57), u'fade_out': 500, u'show_name': u'Untitled Show', 'file_ready': False, u'uri': u'http://localhost//rest/media/142', u'cue_in': 0.009, u'start': datetime.datetime(2017, 6, 5, 13, 59, 41), u'replay_gain': -4.77, 'dst': u'/var/tmp/airtime/pypo/cache/scheduler/142.mp3', u'filesize': 11876319, 'file_ext': '.mp3', u'row_id': 131, u'metadata': {u'rating': None, u'soundcloud_upload_time': None, u'report_datetime': None, u'lyrics': None, u'soundcloud_error_code': None, u'year': u'2015', u'channels': 2, u'bit_rate': 253193, u'buy_this_url': None, u'original_artist': None, u'composer': None, u'mtime': u'2017-06-05 10:40:38', u'contributor': None, u'editedby': None, u'id': 142, u'subject': None, u'radio_station_name': None, u'mood': None, u'copyright': None, u'filepath': u'imported/1/Infected Mushroom/Converting Vegetarians II/Infected_Mushroom_-_Animatronica.mp3', u'soundcloud_id': None, u'description': None, u'catalog_number': None, u'orchestra': None, u'comments': None, u'label': None, u'disc_number': None, u'ftype': u'audioclip', u'filesize': 11876319, u'cueout': u'00:06:15.222834', u'encoded_by': None, u'currentlyaccessing': 0, u'md5': u'98efcad74459d917f889edf733b9687f', u'soundcloud_error_msg': None, u'track_title': u'Animatronica', u'info_url': None, u'lyricist': None, u'import_status': 0, u'conductor': None, u'format': None, u'radio_station_url': None, u'artist_name': u'Infected Mushroom', u'encoder': None, u'audio_source_url': None, u'original_lyricist': None, u'mime': u'audio/mp3', u'cuein': u'00:00:00.008912', u'album_title': u'Converting Vegetarians II', u'genre': u'Electronica', u'hidden': False, u'utime': u'2017-06-05 09:04:10', u'report_organization': None, u'name': u'', u'language': None, u'report_location': None, u'url': None, u'checksum': None, u'bpm': None, u'track_number': 4, u'isrc_number': None, u'length': u'00:06:15.173333', u'sample_rate': 44100, u'artist_url': None, u'soundcloud_link_to_file': None, u'directory': 1, u'lptime': u'2017-06-05 13:03:47', u'replay_gain': u'-4.77', u'owner_id': 1}, u'type': u'file', u'id': 142, u'fade_in': 500}, u'2017-06-05-13-56-06': {u'cue_out': 216.171, u'independent_event': False, u'end': datetime.datetime(2017, 6, 5, 13, 59, 42), u'fade_out': 500, u'show_name': u'Untitled Show', 'file_ready': False, u'uri': u'http://localhost//rest/media/141', u'cue_in': 0.026, u'start': datetime.datetime(2017, 6, 5, 13, 56, 6), u'replay_gain': -7.01, 'dst': u'/var/tmp/airtime/pypo/cache/scheduler/141.mp3', u'filesize': 6213674, 'file_ext': '.mp3', u'row_id': 130, u'metadata': {u'rating': None, u'soundcloud_upload_time': None, u'report_datetime': None, u'lyrics': None, u'soundcloud_error_code': None, u'year': u'2015', u'channels': 2, u'bit_rate': 223512, u'buy_this_url': None, u'original_artist': None, u'composer': None, u'mtime': u'2017-06-05 10:40:08', u'contributor': None, u'editedby': None, u'id': 141, u'subject': None, u'radio_station_name': None, u'mood': None, u'copyright': None, u'filepath': u'imported/1/Benny Smiles/Hotline Miami 2: Wrong Number/Benny_Smiles_-_Hotline_Theme.mp3', u'soundcloud_id': None, u'description': None, u'catalog_number': None, u'orchestra': None, u'comments': None, u'label': None, u'disc_number': None, u'ftype': u'audioclip', u'filesize': 6213674, u'cueout': u'00:03:36.170748', u'encoded_by': None, u'currentlyaccessing': 0, u'md5': u'9a39d190be565ce884f5782321d98f71', u'soundcloud_error_msg': None, u'track_title': u'Hotline Theme', u'info_url': None, u'lyricist': None, u'import_status': 0, u'conductor': None, u'format': None, u'radio_station_url': None, u'artist_name': u'Benny Smiles', u'encoder': None, u'audio_source_url': None, u'original_lyricist': None, u'mime': u'audio/mp3', u'cuein': u'00:00:00.026009', u'album_title': u'Hotline Miami 2: Wrong Number', u'genre': u'Soundtrack', u'hidden': False, u'utime': u'2017-06-05 09:03:34', u'report_organization': None, u'name': u'', u'language': None, u'report_location': None, u'url': None, u'checksum': None, u'bpm': None, u'track_number': 33, u'isrc_number': None, u'length': u'00:03:39.378571', u'sample_rate': 44100, u'artist_url': None, u'soundcloud_link_to_file': None, u'directory': 1, u'lptime': u'2017-06-05 13:00:13', u'replay_gain': u'-7.01', u'owner_id': 1}, u'type': u'file', u'id': 141, u'fade_in': 500}, u'2017-06-05-13-50-42': {u'cue_out': 324.568, u'independent_event': False, u'end': datetime.datetime(2017, 6, 5, 13, 56, 6), u'fade_out': 500, u'show_name': u'Untitled Show', 'file_ready': False, u'uri': u'http://localhost//rest/media/145', u'cue_in': 0.137, u'start': datetime.datetime(2017, 6, 5, 13, 50, 42), u'replay_gain': -7.24, 'dst': u'/var/tmp/airtime/pypo/cache/scheduler/145.mp3', u'filesize': 13066735, 'file_ext': '.mp3', u'row_id': 129, u'metadata': {u'rating': None, u'soundcloud_upload_time': None, u'report_datetime': None, u'lyrics': None, u'soundcloud_error_code': None, u'year': u'2013', u'channels': 2, u'bit_rate': 320087, u'buy_this_url': None, u'original_artist': None, u'composer': None, u'mtime': u'2017-06-05 12:25:33', u'contributor': None, u'editedby': None, u'id': 145, u'subject': None, u'radio_station_name': None, u'mood': None, u'copyright': None, u'filepath': u'imported/1/Arcade Fire/Reflektor/Arcade_Fire_-_Joan_of_Arc.mp3', u'soundcloud_id': None, u'description': None, u'catalog_number': None, u'orchestra': None, u'comments': None, u'label': None, u'disc_number': None, u'ftype': u'audioclip', u'filesize': 13066735, u'cueout': u'00:05:24.568027', u'encoded_by': None, u'currentlyaccessing': 0, u'md5': u'936da99172c12427328650345e2e7975', u'soundcloud_error_msg': None, u'track_title': u'Joan of Arc', u'info_url': None, u'lyricist': None, u'import_status': 0, u'conductor': None, u'format': None, u'radio_station_url': None, u'artist_name': u'Arcade Fire', u'encoder': None, u'audio_source_url': None, u'original_lyricist': None, u'mime': u'audio/mp3', u'cuein': u'00:00:00.136848', u'album_title': u'Reflektor', u'genre': None, u'hidden': False, u'utime': u'2017-06-05 12:25:02', u'report_organization': None, u'name': u'', u'language': None, u'report_location': None, u'url': None, u'checksum': None, u'bpm': None, u'track_number': 7, u'isrc_number': None, u'length': u'00:05:26.52', u'sample_rate': 44100, u'artist_url': None, u'soundcloud_link_to_file': None, u'directory': 1, u'lptime': u'2017-06-05 12:54:48', u'replay_gain': u'-7.24', u'owner_id': 1}, u'type': u'file', u'id': 145, u'fade_in': 500}}
2017-06-05 16:46:47,830 [pypoliqqueue] [INFO ]  waiting 234.169218s until next scheduled item
2017-06-05 16:46:50,111 [pypofile] [INFO ]  copying from http://localhost//rest/media/141 to local cache /var/tmp/airtime/pypo/cache/scheduler/141.mp3
2017-06-05 16:46:50,112 [pypofile] [ERROR]  http://localhost:80/rest/media/141/download
2017-06-05 16:46:52,155 [pypofile] [INFO ]  copying from http://localhost//rest/media/142 to local cache /var/tmp/airtime/pypo/cache/scheduler/142.mp3
2017-06-05 16:46:52,155 [pypofile] [ERROR]  http://localhost:80/rest/media/142/download
aresstokrat picture aresstokrat on 5 Jun 2017

airtime-playout seems to be working. The pyponotify errors indicate something wrong in the connection from liquidsoap to icecast. Are there any additional errors in the liquidsoap log file /var/log/airtime/pypo-liquidsoap/ls_script.log?

hairmare picture hairmare on 5 Jun 2017
👍1

this is what it shows when starting a show:

2017/06/06 10:49:50 [mp3-128:3] Will try again in 5.00 sec.
2017/06/06 10:49:50 [s4:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/144.mp3" (RID 0).
2017/06/06 10:49:50 [schedule_noise_switch:3] Switch to map_metadata_5630 with transition.
2017/06/06 10:49:50 [lang:3] transition called...
2017/06/06 10:49:50 [switch_5628:3] Switch to insert_metadata_5614.
2017/06/06 10:49:50 [cue_cut_5555:3] Cueing in...
2017/06/06 10:49:50 [amplify_5559:3] Overriding amplification: 0.336512.
2017/06/06 10:49:50 [lang:3] timeout --signal=KILL 45 pyponotify --media-id=133 &
2017/06/06 10:49:50 [lang:3] Using stream_format 0
2017/06/06 10:49:50 [lang:3] Using stream_format 0
2017/06/06 10:49:50 [lang:3] Using stream_format 0
2017/06/06 10:49:55 [server:3] New client: localhost.
2017/06/06 10:49:55 [lang:3] dynamic_source.get_id
2017/06/06 10:49:55 [server:3] Client localhost disconnected.
2017/06/06 10:49:56 [mp3-128:3] Connecting mount mp3-128 for source@localhost...
2017/06/06 10:49:56 [mp3-128:2] Connection failed: could not write data to host: Connection refused in write()
2017/06/06 10:49:56 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496667758.49 &
2017/06/06 10:49:56 [mp3-128:3] Will try again in 5.00 sec.
2017/06/06 10:50:02 [mp3-128:3] Connecting mount mp3-128 for source@localhost...
2017/06/06 10:50:02 [mp3-128:2] Connection failed: could not write data to host: Connection refused in write()
2017/06/06 10:50:02 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496667758.49 &
2017/06/06 10:50:02 [mp3-128:3] Will try again in 5.00 sec.
2017/06/06 10:50:08 [mp3-128:3] Connecting mount mp3-128 for source@localhost...
2017/06/06 10:50:08 [mp3-128:2] Connection failed: could not write data to host: Connection refused in write()
2017/06/06 10:50:08 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not write data to host: Connection refused in write()' --stream-id=1 --time=1496667758.49 &
2017/06/06 10:50:08 [mp3-128:3] Will try again in 5.00 sec.
aresstokrat picture aresstokrat on 6 Jun 2017

Thank you !!! I found the error, it was in icecast config.
No 'mount' for /mp3-128

<mount>
<mount-name>/live</mount-name>
<charset>UTF-8</charset>
<fallback-mount>/play</fallback-mount>
<fallback-override>1</fallback-override>
<fallback-when-full>1</fallback-when-full>
</mount>

<mount-name>/mp3-128</mount-name>
<charset>UTF-8</charset>
</mount>

now its runing perfectly fine !! Yesssss!!!! :-)

aresstokrat picture aresstokrat on 6 Jun 2017

Weird, normally LibreTime creates the needed mountpoints on the fly.

hairmare picture hairmare on 6 Jun 2017

Today i found out that services are marked as down in admin panel.
(pypo, liquidsoap)
Icecast's status page shows no mounting points.

BUT - ON AIR is red and stream is playing even now, how that ?
And after few tracks i checked status page and its marked UP again.
(still no mounting point in icecast's status page)

$ sudo systemctl status airtime-playout.service 

● airtime-playout.service - Airtime Playout Service
   Loaded: loaded (/etc/systemd/system/airtime-playout.service; enabled)
   Active: active (running) since Π’Ρ‚ 2017-06-06 10:54:48 +03; 1 day 3h ago
 Main PID: 22306 (airtime-playout)
   CGroup: /system.slice/airtime-playout.service
           └─22306 /usr/bin/python /usr/bin/airtime-playout

июн 07 13:59:39 raspberrypi airtime-playout[22306]: .datetime(2017, 6, 7, 11, 26, 25), u'replay_gain': -4.24, 'dst': u'/var/tmp/airtime/pypo/cache/scheduler/173.mp3', u'file...'soundcloud
июн 07 13:59:39 raspberrypi airtime-playout[22306]: nt': False, u'end': datetime.datetime(2017, 6, 7, 11, 43, 21), u'fade_out': 100, u'show_name': u'12h', 'file_ready': True...e/pypo/cach
июн 07 13:59:39 raspberrypi airtime-playout[22306]: , u'fade_in': 100}, u'2017-06-07-11-36-05': {u'cue_out': 209.2, u'independent_event': False, u'end': datetime.datetime(20...e.datetime(
июн 07 13:59:39 raspberrypi airtime-playout[22306]: ': None, u'report_location': None, u'url': None, u'checksum': None, u'bpm': None, u'track_number': 3, u'isrc_number': None, u'length...
июн 07 13:59:39 raspberrypi airtime-playout[22306]: 2017-06-07 13:59:39,278 [pypoliqqueue] [INFO ]  waiting 216.72143s until next scheduled item
июн 07 13:59:39 raspberrypi airtime-playout[22306]: 2017-06-07 13:59:39,407 [pypofetch] [INFO ]  File '/var/tmp/airtime/pypo/cache/scheduler/165.mp3' removed
июн 07 13:59:39 raspberrypi airtime-playout[22306]: 2017-06-07 13:59:39,483 [pypofetch] [INFO ]  File '/var/tmp/airtime/pypo/cache/scheduler/254.mp3' removed
июн 07 13:59:39 raspberrypi airtime-playout[22306]: 2017-06-07 13:59:39,484 [pypofetch] [INFO ]  Loop #277
июн 07 13:59:40 raspberrypi airtime-playout[22306]: 2017-06-07 13:59:40,296 [pypofile] [INFO ]  copying from http://localhost//rest/media/166 to local cache /var/tmp/airtime...ler/166.mp3
июн 07 13:59:40 raspberrypi airtime-playout[22306]: 2017-06-07 13:59:40,297 [pypofile] [ERROR]  http://localhost:80/rest/media/166/download
Hint: Some lines were ellipsized, use -l to show in full.

$ sudo systemctl status airtime-liquidsoap.service 

● airtime-liquidsoap.service - Airtime Liquidsoap Service
   Loaded: loaded (/etc/systemd/system/airtime-liquidsoap.service; enabled)
   Active: active (running) since Π’Ρ‚ 2017-06-06 10:57:46 +03; 1 day 3h ago
 Main PID: 23252 (liquidsoap)
   CGroup: /system.slice/airtime-liquidsoap.service
           └─23252 airtime-liquidsoap /usr/local/lib/python2.7/dist-packages/airtime_playout-1.0-py2.7.egg/liquidsoap/ls_script.liq --verbose -f

июн 07 14:03:17 raspberrypi airtime-liquidsoap[23252]: 2017/06/07 14:03:17 [cue_cut_5555:3] Cueing in...
июн 07 14:03:17 raspberrypi airtime-liquidsoap[23252]: 2017/06/07 14:03:17 [amplify_5559:3] Overriding amplification: 0.436516.
июн 07 14:03:17 raspberrypi airtime-liquidsoap[23252]: 2017/06/07 14:03:17 [lang:3] timeout --signal=KILL 45 pyponotify --media-id=237 &
июн 07 14:03:17 raspberrypi airtime-liquidsoap[23252]: 2017/06/07 14:03:17 [lang:3] Using stream_format 0
июн 07 14:03:17 raspberrypi airtime-liquidsoap[23252]: 2017/06/07 14:03:17 [lang:3] Using stream_format 0
июн 07 14:03:17 raspberrypi airtime-liquidsoap[23252]: 2017/06/07 14:03:17 [lang:3] Using stream_format 0
июн 07 14:03:21 raspberrypi airtime-liquidsoap[23252]: #########################################
июн 07 14:03:21 raspberrypi airtime-liquidsoap[23252]: #           *** pypo  ***               #
июн 07 14:03:21 raspberrypi airtime-liquidsoap[23252]: #     pypo notification gateway         #
июн 07 14:03:21 raspberrypi airtime-liquidsoap[23252]: #########################################

@hairmare

Weird, normally LibreTime creates the needed mountpoints on the fly.

I did't knew that.
I was making all changes by hands. (including mount points)
Where it searches for icecast's config and what rights does it need?
Couse i have config not in default directory.

aresstokrat picture aresstokrat on 7 Jun 2017

Where it searches for icecast's config and what rights does it need?
Couse i have config not in default directory.

It's probably doing it through the api using the admin username/password combo.

The default config as installed on the vagrant boxes seems to work. I haven't done any real testing to figure out how it works and what happens when the password is changed.

hairmare picture hairmare on 7 Jun 2017

Strange thing happeping. After restart of Pi , no Pypo and Analyzer service started.
I checked
systemctl list-unitsand found that there is no such services loaded. How that can be?
and

● airtime-celery.service loaded failed failed LibreTime Celery Service

still i see them in directory

$ ls -la /etc/systemd/system
ΠΈΡ‚ΠΎΠ³ΠΎ 72
drwxr-xr-x 13 root root 4096 июн  5 14:06 .
drwxr-xr-x  6 root root 4096 ΠΌΠ°ΠΉ 15 13:03 ..
-rwxr-xr-x  1 pi   pi    181 июн  9 11:23 airtime_analyzer.service
-rwxr-xr-x  1 pi   pi    361 ΠΌΠ°ΠΉ 31 16:48 airtime-celery.service
-rwxr-xr-x  1 pi   pi    177 июн  9 11:22 airtime-liquidsoap.service
-rwxr-xr-x  1 pi   pi    171 июн  9 11:23 airtime-playout.service

[UPDATE 1]
but daemon-reload does't help.
i cant run them with
sudo systemctl start-airtime-playout.service

sudo systemctl list-unit-files

airtime-celery.service                 enabled 
airtime-liquidsoap.service             enabled 
airtime-playout.service                disabled
airtime_analyzer.service               disabled

[UPDATE 2]
this is what i did next (but it does't help, maybe i need to restart pi):

pi@raspberrypi:~ $ sudo systemctl enable airtime-playout.service 
Created symlink from /etc/systemd/system/multi-user.target.wants/airtime-playout.service to /etc/systemd/system/airtime-playout.service.
pi@raspberrypi:~ $ sudo systemctl enable airtime_analyzer.service 
Created symlink from /etc/systemd/system/multi-user.target.wants/airtime_analyzer.service to /etc/systemd/system/airtime_analyzer.service.
pi@raspberrypi:~ $ sudo systemctl status airtime-playout.service 
● airtime-playout.service - Airtime Playout Service
   Loaded: loaded (/etc/systemd/system/airtime-playout.service; enabled)
   Active: inactive (dead)
pi@raspberrypi:~ $ sudo systemctl start airtime-playout.service 
pi@raspberrypi:~ $ sudo systemctl start airtime_analyzer.service

how to find origin of disabling ? what log should i read?

[UPDATE 3]

Can not connect to the streaming server
could not connect to host: Connection refused in connect()

In stream section of admin panel. How that :(((( I did't change anything. Icecast2 is working with same config :((

[UPDATE 4]

2017/06/15 16:12:54 [FireFM:3] Connecting mount mp3-128 for source@localhost...
2017/06/15 16:12:54 [FireFM:2] Connection failed: could not connect to host: Connection refused in connect()
2017/06/15 16:12:54 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not connect to host: Connection refused in connect()' --stream-id=1 --time=1497532098.24 &
2017/06/15 16:12:54 [FireFM:3] Will try again in 5.00 sec.
2017/06/15 16:12:55 [FireFM(dot)1:3] Connecting mount aac96 for source@localhost...
2017/06/15 16:12:55 [FireFM(dot)1:2] Connection failed: could not connect to host: Connection refused in connect()
2017/06/15 16:12:55 [lang:3] timeout --signal=KILL 45 pyponotify --error='could not connect to host: Connection refused in connect()' --stream-id=2 --time=1497532098.24 &
2017/06/15 16:12:55 [FireFM(dot)1:3] Will try again in 5.00 sec.

and finaly its come to an state
Connected to the streaming serverby itself in 15 minutes. I dont know why, did't change anything. :-(

aresstokrat picture aresstokrat on 15 Jun 2017

This issue was moved to http://discourse.libretime.org/t/liquidsoap-constantly-failing/28

Robbt picture Robbt on 19 Oct 2017

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please chat to us on discourse or ask for help on our chat if you have any questions or need further assistance with this issue.

lock[bot] picture lock[bot] on 20 Oct 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

Robbt picture Robbt  Β·  9Comments
celianvdb picture celianvdb  Β·  11Comments
solohtml picture solohtml  Β·  8Comments
hairmare picture hairmare  Β·  9Comments
frecuencialibre picture frecuencialibre  Β·  9Comments