Icecast Streaming Media Server Forum Index Icecast Streaming Media Server
Icecast is a Xiph Foundation Project
 
 FAQFAQ   SearchSearch   MemberlistMemberlist   UsergroupsUsergroups   RegisterRegister 
 ProfileProfile   Log in to check your private messagesLog in to check your private messages   Log inLog in 

Intermittant socket timeout

 
Post new topic   Reply to topic    Icecast Streaming Media Server Forum Index -> Source Clients
View previous topic :: View next topic  
Author Message
mlakewood



Joined: 13 May 2011
Posts: 1

PostPosted: Tue May 17, 2011 6:29 am    Post subject: Intermittant socket timeout Reply with quote

Hi all,

I've written my own source client using shoutpy (http://pypi.python.org/pypi/shoutpy) . The problem im having is that every few days the source client gets a socket error. I did an strace of the network and I get

19:17:33 socket(PF_NETLINK, SOCK_RAW, 0) = 5
19:17:33 bind(5, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0
19:17:33 getsockname(5, {sa_family=AF_NETLINK, pid=29412, groups=00000000}, [12]) = 0
19:17:33 sendto(5, "\24\0\0\0\26\0\1\3\315\301\313M\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20
19:17:33 recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"0\0\0\0\24\0\2\0\315\301\313M\344r\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 108
19:17:33 recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\315\301\313M\344r\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 128
19:17:33 recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\315\301\313M\344r\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20
19:17:33 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
19:17:33 connect(4, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("127.0.1.1")}, 16) = 0
19:17:33 getsockname(4, {sa_family=AF_INET, sin_port=htons(56746), sin_addr=inet_addr("127.0.1.1")}, [16]) = 0
19:17:33 connect(4, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
19:17:33 connect(4, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("192.168.0.156")}, 16) = 0
19:17:33 getsockname(4, {sa_family=AF_INET, sin_port=htons(51862), sin_addr=inet_addr("192.168.0.156")}, [16]) = 0
19:17:33 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 4
19:17:33 connect(4, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("127.0.1.1")}, 16) = -1 ECONNREFUSED (Connection refused)
19:17:33 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 4
19:17:33 connect(4, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("192.168.0.156")}, 16) = 0
19:17:33 sendto(4, "SOURCE /classical.mp3 HTTP/1.0\r\n"..., 236, 0, NULL, 0) = 236
19:17:33 recvfrom(4, "HTTP/1.0 200 OK\r\n\r\n", 1024, 0, NULL, NULL) = 19
19:17:33 socket(PF_NETLINK, SOCK_RAW, 0) = 5
19:17:33 bind(5, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0
19:17:33 getsockname(5, {sa_family=AF_NETLINK, pid=29412, groups=00000000}, [12]) = 0
19:17:33 sendto(5, "\24\0\0\0\26\0\1\3\315\301\313M\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20
19:17:33 recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"0\0\0\0\24\0\2\0\315\301\313M\344r\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 108
19:17:33 recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\315\301\313M\344r\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 128
19:17:33 recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\315\301\313M\344r\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20
19:17:33 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 5
19:17:33 connect(5, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.0.161")}, 16) = 0
19:17:33 sendto(5, "POST /remotelog/shoutgen/log/ HT"..., 129, 0, NULL, 0) = 129
19:17:33 sendto(5, "threadName=MainThread&name=29412"..., 487, 0, NULL, 0) = 487


the icecast logs say
[2011-05-12 19:17:31] DBUG stats/modify_node_event update node clients (0)
[2011-05-12 19:17:31] DBUG stats/modify_node_event update node sources (0)
[2011-05-12 19:17:32] DBUG stats/modify_node_event update node clients (1)
[2011-05-12 19:17:32] DBUG stats/modify_node_event update node connections (33)
[2011-05-12 19:17:32] INFO connection/_handle_source_request Source logging in at mountpoint "/thewho.mp3"
[2011-05-12 19:17:32] DBUG connection/connection_complete_source sources count is 0
[2011-05-12 19:17:32] DBUG source/source_apply_mount Applying mount information for "/thewho.mp3"
[2011-05-12 19:17:32] DBUG format-mp3/format_mp3_apply_settings sending metadata interval 16000
[2011-05-12 19:17:32] DBUG format-mp3/format_mp3_apply_settings charset ISO8859-1
[2011-05-12 19:17:32] DBUG source/source_update_settings public set to 0
[2011-05-12 19:17:32] DBUG source/source_update_settings max listeners to -1
[2011-05-12 19:17:32] DBUG source/source_update_settings queue size to 524288
[2011-05-12 19:17:32] DBUG source/source_update_settings burst size to 65535
[2011-05-12 19:17:32] DBUG source/source_update_settings source timeout to 20
[2011-05-12 19:17:32] DBUG source/source_update_settings fallback_when_full to 0
[2011-05-12 19:17:32] DBUG connection/connection_complete_source source is ready to start
[2011-05-12 19:17:32] DBUG fserve/fserve_add_client_callback Adding client to file serving engine
[2011-05-12 19:17:32] DBUG source/source_init Source creation complete
[2011-05-12 19:17:32] DBUG stats/modify_node_event update node sources (1)
[2011-05-12 19:17:32] DBUG stats/process_source_event new source stat /thewho.mp3
[2011-05-12 19:17:32] DBUG stats/process_source_event new node listenurl (http://ice1.local:8000/thewho.mp3)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node listener_peak (0)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node public (0)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node server_name (thewho)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node server_description (Unspecified description)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node server_url (http://ice1.local:8000/thewho.mp3)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node genre (Rock)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node server_type (audio/mpeg)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node max_listeners (unlimited)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node source_ip (192.168.0.156)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node user_agent (libshout/2.2.2)
[2011-05-12 19:17:32] DBUG stats/modify_node_event update node source_client_connections (21)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node listeners (0)
[2011-05-12 19:17:32] DBUG stats/modify_node_event update node listenurl (http://ice1.local:8000/thewho.mp3)
[2011-05-12 19:17:32] DBUG stats/modify_node_event update node source_total_connections (21)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node slow_listeners (0)
[2011-05-12 19:17:32] DBUG stats/modify_node_event update node listeners (0)
[2011-05-12 19:17:32] DBUG stats/modify_node_event update node listener_peak (0)
[2011-05-12 19:17:32] DBUG stats/process_source_event new node stream_start (Thu, 12 May 2011 19:17:32 +0800)
[2011-05-12 19:17:32] INFO source/source_main listener count on /thewho.mp3 now 0
[2011-05-12 19:17:33] DBUG stats/process_source_event new node total_bytes_read (0)
[2011-05-12 19:17:33] DBUG stats/process_source_event new node total_bytes_sent (0)
[2011-05-12 19:17:33] DBUG stats/modify_node_event update node listeners (0)
[2011-05-12 19:17:33] DBUG stats/modify_node_event update node clients (2)
[2011-05-12 19:17:33] DBUG stats/modify_node_event update node connections (34)
2011-05-12 19:17:34] DBUG stats/modify_node_event update node listeners (0)
[2011-05-12 19:17:37] DBUG stats/modify_node_event update node total_bytes_read (0)
[2011-05-12 19:17:37] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2011-05-12 19:17:38] DBUG stats/modify_node_event update node total_bytes_read (0)
[2011-05-12 19:17:38] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2011-05-12 19:17:42] DBUG stats/modify_node_event update node total_bytes_read (0)
[2011-05-12 19:17:42] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2011-05-12 19:17:43] DBUG stats/modify_node_event update node total_bytes_read (0)
[2011-05-12 19:17:43] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2011-05-12 19:17:47] DBUG stats/modify_node_event update node total_bytes_read (0)
[2011-05-12 19:17:47] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2011-05-12 19:17:48] DBUG stats/modify_node_event update node total_bytes_read (0)
[2011-05-12 19:17:48] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2011-05-12 19:17:52] DBUG stats/modify_node_event update node total_bytes_read (0)
[2011-05-12 19:17:52] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2011-05-12 19:17:53] DBUG source/get_next_buffer last 1305199052, timeout 20, now 1305199073
[2011-05-12 19:17:53] WARN source/get_next_buffer Disconnecting source due to socket timeout
[2011-05-12 19:17:53] INFO source/source_shutdown Source "/thewho.mp3" exiting
[2011-05-12 19:17:53] DBUG source/source_clear_source clearing source "/thewho.mp3"
[2011-05-12 19:17:53] DBUG source/source_free_source freeing source "/thewho.mp3"
[2011-05-12 19:17:53] DBUG stats/modify_node_event update node total_bytes_read (0)
[2011-05-12 19:17:53] DBUG stats/modify_node_event update node total_bytes_sent (0)
[2011-05-12 19:17:53] DBUG stats/process_source_event delete source node /thewho.mp3
[2011-05-12 19:17:53] DBUG stats/modify_node_event update node clients (1)
[2011-05-12 19:17:53] DBUG stats/modify_node_event update node sources (1)
[2011-05-12 19:17:54] DBUG source/get_next_buffer last 1305199053, timeout 20, now 1305199074
[2011-05-12 19:17:54] WARN source/get_next_buffer Disconnecting source due to socket timeout
[2011-05-12 19:17:54] INFO source/source_shutdown Source "/classical.mp3" exiting
[2011-05-12 19:17:54] DBUG source/source_clear_source clearing source "/classical.mp3"
[2011-05-12 19:17:54] DBUG source/source_free_source freeing source "/classical.mp3"
[2011-05-12 19:17:54] DBUG stats/process_source_event delete source node /classical.mp3

So it appears that for some reason im getting a timeout and then icecast is disconnecting from the socket, which causes a socket error on my end.

My python code that is sending the data is below

Code:
def Stream(self):
        self.log.debug("--> stream()")
        #self.log.debug("ZZZ: " + str(self.m_songList))
        if len(self.m_songList) == 0:
            self.log.critical("no songs in playlist. Exiting...")
            return 16

        #setup S3
       
       
        S3Conn = S3Bucket(self.m_conf.configList["S3_BUCKET"], self.m_conf.configList["S3_ACCESS_KEY"], self.m_conf.configList["S3_SECRET"])

        stream = shoutpy.Shout()
        # print "Using libshout version % stream" % stream.
   
        stream.host = self.m_mountInfo["HOST"]
        #stream.port = self.m_mountInfo["PORT"]
        stream.user = self.m_mountInfo["USER"]
        stream.password = self.m_mountInfo["PASSWORD"]
        stream.mount = str(self.m_jsonPlayList["fields"]["mount"])
        stream.format = shoutpy.FORMAT_MP3
        stream.protocol = shoutpy.PROTOCOL_HTTP
        stream.name = str(self.m_jsonPlayList["fields"]["name"])
        stream.genre = str(self.m_jsonPlayList["fields"]["genre"])
        stream.url = str(self.m_jsonPlayList["fields"]["url"])
        #stream.nonblocking = True
        # stream.public = 0 | 1
        # stream.audio_info = { 'key': 'val', ... }
        #  (keys are shout.SHOUT_AI_BITRATE, shout.SHOUT_AI_SAMPLERATE,
        #   shout.SHOUT_AI_CHANNELS, shout.SHOUT_AI_QUALITY)
       

        stream.open()


       
        total = 0
        st = time.time()
       
        self.log.debug("stream.while()")
        while(1):
            self.log.debug("Length of list: %s" % (len(self.m_songList)))

            if len(self.m_songList) == 0:
                pl = PlayList.PlayList(self.m_jsonPlayList,self.m_conf)
                pl.GetPlayList(self.m_conf,self.m_jsonPlayList["pk"])
                self.m_songList = pl.m_list
           
            numrows = len(self.m_songList)
            randomNum = random.randint(0, numrows - 1)
            self.log.debug(randomNum)
            key = self.m_songList[randomNum]["fields"]["path"]

            try:
                self.log.debug("opening file %s " % key.encode("utf_8"))
                song = self.m_songList[randomNum]["fields"]["track_name"].encode("utf_8")
                artist = self.m_songList[randomNum]["fields"]["track_artist"].encode("utf_8")
                self.log.info("%s - %s" % (song, artist))
               
                f = S3Conn.get(key)
               
                stream.metadata = {'song': self.m_songList[randomNum]["fields"]["track_name"].encode("utf_8") + " - " + self.m_songList[randomNum]["fields"]["track_artist"].encode("utf_8")}
                self.recordSongPlayed(self.m_songList[randomNum], self.m_jsonPlayList)

                buf = f.read(4096)
                read_bytes = 4096
                while (1):
                    try:
                        stream.send(buf)
                    except RuntimeError, e:
                        self.log.critical("Connected: %s" % stream.connected)
                        self.log.critical(stream.error)
                        self.log.critical(stream.errno)
                        self.log.exception()
                        exit()
                    except IOError as e:
                        self.log.critical("Error: %s, Errno: %s. Bytes Read: %s, retrying..." % (e, e.errno, read_bytes))
                        self.log.exception()
                        #exit()
                    except:
                        self.log.critical("Unexpected Error: %s" % sys.exc_info()[0])
                        self.log.exception()
                        exit()
                       
                    try:
                        buf = f.read(512)
                    except RuntimeError, e:
                        self.log.critical("Read File: %s" % e)
                        self.log.exception()
                        exit()
                    except IOError as e:
                        self.log.critical("File: Error: %s, Errno: %s. Bytes Read: %s, retrying..." % (e, e.errno, read_bytes))
                        self.log.exception()
                        #exit()
                    except:
                        self.log.critical("File: Secondary Read. Unexpected Error: %s" % sys.exc_info()[0])
                        self.log.exception()
                        exit()
                   
                    read_bytes += len(buf)
                   
                    if len(buf) == 0:
                        break
                    stream.sync()

                f.close()
            except(IOError, os.error), why:
                self.log.critical("Error opening file %s" % f)
                self.log.critical(str(why))
                self.log.exception("Exception while opening file")
            except:
                self.log.critical("Initial Open. Unexpected Error: %s" % sys.exc_info()[0])
                self.log.exception()
                exit()
           
           
            del self.m_songList[randomNum]

       

        stream.close()



Im running on ubuntu 10.04. icecast 2.3.2, shoutpy 1.0.0 libshout 2.2.2 .

Any help would be greatly appreciated!

Cheers

Mark
Back to top
View user's profile Send private message
karlH
Code Warrior
Code Warrior


Joined: 13 Jun 2005
Posts: 5476
Location: UK

PostPosted: Tue May 17, 2011 7:38 pm    Post subject: Reply with quote

based on the strace available, we see

19:17:33 connect(4, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("192.168.0.156")}, 16) = 0
19:17:33 sendto(4, "SOURCE /classical.mp3 HTTP/1.0\r\n"..., 236, 0, NULL, 0) = 236
19:17:33 recvfrom(4, "HTTP/1.0 200 OK\r\n\r\n", 1024, 0, NULL, NULL) = 19

That is the login matching up with icecast as
[2011-05-12 19:17:32] INFO connection/_handle_source_request Source logging in at mountpoint "/thewho.mp3"

but there are no further entries of sendto or write on fd 4, so if none occur for 20 seconds then icecast does

[2011-05-12 19:17:53] DBUG source/get_next_buffer last 1305199052, timeout 20, now 1305199073

I would suggest you check the debug from the source client, see if there is a stall occurring, you know it reads the response of ok but it either ignores it or gets stuck doing something else.

karl
Back to top
View user's profile Send private message Send e-mail Visit poster's website
Display posts from previous:   
Post new topic   Reply to topic    Icecast Streaming Media Server Forum Index -> Source Clients All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum


Powered by phpBB © 2001, 2002 phpBB Group
subRebel style by ktauber