Liquidsoap constantly failing

From @aresstokrat on Wed May 31 2017 10:34:45 GMT+0000 (UTC)

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?

Copied from original issue: https://github.com/LibreTime/libretime/issues/213

From @ghost on Wed May 31 2017 10:39:42 GMT+0000 (UTC)

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

From @aresstokrat on Wed May 31 2017 10:45:15 GMT+0000 (UTC)

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.

From @hairmare on Wed May 31 2017 11:41:51 GMT+0000 (UTC)

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.

From @aresstokrat on Wed May 31 2017 12:10:27 GMT+0000 (UTC)

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.

From @aresstokrat on Wed May 31 2017 12:16:19 GMT+0000 (UTC)

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()

From @Robbt on Wed May 31 2017 12:17:42 GMT+0000 (UTC)

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 ?

From @hairmare on Wed May 31 2017 12:30:32 GMT+0000 (UTC)

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 :frowning:

systemctl stop airtime-playout
sudo -u www-data airtime-playout

From @aresstokrat on Wed May 31 2017 13:00:02 GMT+0000 (UTC)

checked status page, all this marked as dawn again:

Media Analzyer
Pypo
Liquidsoap

From @aresstokrat on Wed May 31 2017 14:30:07 GMT+0000 (UTC)

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()

From @hairmare on Wed May 31 2017 16:22:11 GMT+0000 (UTC)

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.

From @aresstokrat on Thu Jun 01 2017 07:21:49 GMT+0000 (UTC)

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

From @aresstokrat on Thu Jun 01 2017 07:23:11 GMT+0000 (UTC)

all 3 services down

From @aresstokrat on Thu Jun 01 2017 12:24:43 GMT+0000 (UTC)

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

From @hairmare on Thu Jun 01 2017 17:27:17 GMT+0000 (UTC)

> 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.

From @aresstokrat on Fri Jun 02 2017 10:38:47 GMT+0000 (UTC)

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?

From @hairmare on Fri Jun 02 2017 15:49:01 GMT+0000 (UTC)

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, …).

From @aresstokrat on Mon Jun 05 2017 12:19:46 GMT+0000 (UTC)

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

From @aresstokrat on Mon Jun 05 2017 13:48:12 GMT+0000 (UTC)

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

From @hairmare on Mon Jun 05 2017 18:09:41 GMT+0000 (UTC)

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?