Problems with 1114

[peller]

I haven’t tried a nightly in a while, so forgive me if any of this is common knowledge.

I’m running on a NSLU2 and I wiped out my old databases (if I didn’t, mt-daapd’s parse errors on old playlist data turned out to be fatal) I get what seem to be random crashes after playing several songs and leaving things idle. The logs don’t seem to tell much. Here’s what I saw with -d 9 turned on:

2005-11-16 11:59:46: AddRecordToResponseList: Music Library._daap._tcp.local. (SRV) already in list
2005-11-16 11:59:46: AddRecordToResponseList: sluggo.local. (Addr) already in list
2005-11-16 11:59:46: mDNS_Execute
2005-11-16 11:59:46: SendResponses: Sending 0 Deregistrations, 0 Announcements,
2 Answers, 0 Additionals on 00051B60
2005-11-16 11:59:46: SendResponses: Next in 2013265920 ticks
2005-11-16 11:59:46: select(6, 0.168945)
2005-11-16 11:59:46: SocketDataReady got a packet from 192.168.0.100 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 11:59:46: Received Response from 192.168.0.100 addressed to 224.0.0.251 on 00051B60 TTL 255 with 0 Questions, 2 Answers, 0 Authorities, 0 Additionals
2005-11-16 11:59:46: select(6, 0.167968)
2005-11-16 11:59:46: mDNS_Execute
2005-11-16 11:59:46: select(6, 1963336.721679)
2005-11-16 11:59:51: SocketDataReady got a packet from 192.168.0.106 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 11:59:51: Received Query from 192.168.0.106 :5353 to 224.0.0.251
:5353 on 0x00051B60 with 1 Question, 0 Answers, 0 Authorities, 0 Additionals
2005-11-16 11:59:51: AddRecordToResponseList: Music Library._daap._tcp.local. (TXT) already in list
2005-11-16 11:59:51: mDNS_Execute
2005-11-16 11:59:51: SendResponses: Sending 0 Deregistrations, 0 Announcements,
1 Answer, 0 Additionals on 00051B60
2005-11-16 11:59:51: SendResponses: Next in 2013265920 ticks
2005-11-16 11:59:51: select(6, 0.169921)
2005-11-16 11:59:51: SocketDataReady got a packet from 192.168.0.100 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 11:59:51: Received Response from 192.168.0.100 addressed to 224.0.0.251 on 00051B60 TTL 255 with 0 Questions, 1 Answer, 0 Authorities, 0 Additionals
2005-11-16 11:59:51: select(6, 0.168945)
2005-11-16 11:59:51: mDNS_Execute
2005-11-16 11:59:51: select(6, 1963331.740234)
2005-11-16 12:00:00: Processing rendezvous message
2005-11-16 12:00:00: Rendezvous socket closed (daap server crashed?) Aborting.
2005-11-16 12:00:00: Aborting

Yeah, the timestamp is a bit weird. A coincidence, I think? It might have been the moment I tried accessing mt-daap from iTunes on my Mac, but I’m not sure. I’ll try to get more logs and post here.

Post edited by: peller, at: 2005/11/17 02:42

[peller]

and hitting the web site (status page) seems to bring down the server intermittently as well. Will try to get level 9 logs on that.

[peller]

same thing, different timestamp. .100 is the slug, .106 is my Linux box, running rhythmbox 0.9.1 (hey, could it be something rhythmbox is doing? I haven’t had time to play tunes from my SoundBridge yet with this build)

2005-11-16 12:41:39: SendResponses: Sending 0 Deregistrations, 0 Announcements, 1 Answer, 0 Additionals on 00051B60
2005-11-16 12:41:39: SendResponses: Next in 4976 ticks
2005-11-16 12:41:39: select(6, 0.104492)
2005-11-16 12:41:39: SocketDataReady got a packet from 192.168.0.100 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 12:41:39: Received Response from 192.168.0.100 addressed to 224.0.0.251 on 00051B60 TTL 255 with 0 Questions, 1 Answer, 0 Authorities, 0 Additionals
2005-11-16 12:41:39: select(6, 0.103515)
2005-11-16 12:41:39: mDNS_Execute
2005-11-16 12:41:39: select(6, 4.756835)
2005-11-16 12:41:41: SocketDataReady got a packet from 192.168.0.106 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 12:41:41: Received Query from 192.168.0.106 :5353 to 224.0.0.251 :5353 on 0x00051B60 with 1 Question, 0 Answers, 0 Authorities, 0 Additionals
2005-11-16 12:41:41: AddRecordToResponseList: Music Library._daap._tcp.local. (TXT) already in list
2005-11-16 12:41:41: mDNS_Execute
2005-11-16 12:41:41: SendResponses: Sending 0 Deregistrations, 0 Announcements, 1 Answer, 0 Additionals on 00051B60
2005-11-16 12:41:41: SendResponses: Next in 3614 ticks
2005-11-16 12:41:41: select(6, 0.104492)
2005-11-16 12:41:41: SocketDataReady got a packet from 192.168.0.100 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 12:41:41: Received Response from 192.168.0.100 addressed to 224.0.0.251 on 00051B60 TTL 255 with 0 Questions, 1 Answer, 0 Authorities, 0 Additionals
2005-11-16 12:41:41: select(6, 0.103515)
2005-11-16 12:41:41: mDNS_Execute
2005-11-16 12:41:41: select(6, 3.429687)
2005-11-16 12:41:43: SocketDataReady got a packet from 192.168.0.106 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 12:41:43: Received Query from 192.168.0.106 :5353 to 224.0.0.251 :5353 on 0x00051B60 with 1 Question, 0 Answers, 0 Authorities, 0 Additionals
2005-11-16 12:41:43: AddRecordToResponseList: Music Library._daap._tcp.local. (SRV) already in list
2005-11-16 12:41:43: AddRecordToResponseList: sluggo.local. (Addr) already in list
2005-11-16 12:41:43: mDNSPlatformTimeNow went backwards by 6 ticks; setting correction factor to 12
2005-11-16 12:41:43: mDNS_Execute
2005-11-16 12:41:43: SendResponses: Sending 0 Deregistrations, 0 Announcements, 1 Answer, 1 Additional on 00051B60
2005-11-16 12:41:43: SendResponses: Next in 793 ticks
2005-11-16 12:41:43: select(6, 0.111328)
2005-11-16 12:41:43: SocketDataReady got a packet from 192.168.0.100 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 12:41:43: Received Response from 192.168.0.100 addressed to 224.0.0.251 on 00051B60 TTL 255 with 0 Questions, 1 Answer, 0 Authorities, 1 Additional
2005-11-16 12:41:43: select(6, 0.110351)
2005-11-16 12:41:43: mDNS_Execute
2005-11-16 12:41:43: select(6, 0.666992)
2005-11-16 12:41:44: mDNS_Execute
2005-11-16 12:41:44: Announcing _services._dns-sd._udp.local. (PTR) 0
2005-11-16 12:41:44: Announcing _daap._tcp.local. (PTR) 0
2005-11-16 12:41:44: Announcing _services._dns-sd._udp.local. (PTR) 0
2005-11-16 12:41:44: Announcing _http._tcp.local. (PTR) 0
2005-11-16 12:41:44: SendResponses: Sending 0 Deregistrations, 4 Announcements, 0 Answers, 0 Additionals on 00051B60
2005-11-16 12:41:44: SendResponses: Next in 2013265920 ticks
2005-11-16 12:41:44: select(6, 0.109375)
2005-11-16 12:41:44: SocketDataReady got a packet from 192.168.0.100 to 224.0.0.251 on interface 192.168.0.100/ixp0/2
2005-11-16 12:41:44: Received Response from 192.168.0.100 addressed to 224.0.0.251 on 00051B60 TTL 255 with 0 Questions, 4 Answers, 0 Authorities, 0 Additionals
2005-11-16 12:41:44: select(6, 0.107421)
2005-11-16 12:41:44: mDNS_Execute
2005-11-16 12:41:44: select(6, 1965386.326171)
2005-11-16 12:43:13: Processing rendezvous message
2005-11-16 12:43:13: Rendezvous socket closed (daap server crashed?) Aborting.
2005-11-16 12:43:13: Aborting

[rpedde]

That’s the race that’s been there last two versions. Still looking for it.

I’ve spent *hours* looking for it and can’t find squat.

The thing of it is, I think this is also the thing that makes it hang on shutdown occasionally, so I really want to find this.

[peller]

FWIW, I always had a web browser open on port 3689 or whatever, which refreshes, so I suppose it could be a race involving the web thread? OTOH, I don’t think I saw anything in the log from the web client’s IP at the time of the crash. I didn’t try to reproduce it without the web.

[rpedde]

Yup, it turns out it was a race involving the code that updated the status description of the threads — the part that is shown on the status screen.

Turns out you didn’t have to have the web page open to make it crash, but it made the race more likely.

Anyway… should be fixed in 1116. Let me know.

— Ron

[Author]

Posts