PS3 Media Server

Official PS3 Media Server Forum

Skip to content

Lost connection/NPE with some renderers

Discuss alternative media renderers (not PS3) supported by PS3 Media Server (like Xbox 360 and TVs)
Post a reply

Server drops out for a few seconds

Postby Jarl » Mon Nov 19, 2012 10:35 am

For some reason the ps3 media server drops out for a few seconds every now and then. It ruins the experience when playing a movie, because you have to browse through your folders to the movie and find the time you had reached in it.

I have tried making my IP static (both on the TV side and binding the TV's MAC to the same ip on the DHCP server).
I have checked the cables.
My computer doesn't go into sleep mode.

With Serviio this problem did not exists, but there were other problems (suffice to say I prefer ps3 media server).
With TVersity I experienced something similar, with the difference that I had to restart the router, whereas I with ps3 media server only have to "search for servers" on the TV.

EDIT:
When using ps3 media server I can never get to the 20 minute mark (and often not even 13), before the server vanish for two seconds (which means I'm thrown back to the select media server screen).
When using windows media player this never happens.
Same with TVersity (checked again and the mentioned similar problem as expected has nothing to do with this).
Same with Serviio (as I mentioned before).

It seems like this might be a bug in ps3 media server.

EDIT2:
I'm using PS3 Media Server 1.72.0
I'm not transcoding or remuxing.

EDIT3:
Updated java 32 bit to version 7 update 9. Problem persists.
To be more precise I'll say the server vanish for four seconds.

EDIT4:
It's a NULL pointer exception.

Debug log:
Code: Select all
INFO  2012-11-19 14:23:19.025 [main] Starting PS3 Media Server 1.72.0
INFO  2012-11-19 14:23:19.025 [main] by shagrath / 2008-2012
INFO  2012-11-19 14:23:19.025 [main] http://ps3mediaserver.org
INFO  2012-11-19 14:23:19.025 [main] https://github.com/ps3mediaserver/ps3mediaserver
INFO  2012-11-19 14:23:19.025 [main]
INFO  2012-11-19 14:23:19.025 [main] Build: d9fd0a44c (2012-11-18)
INFO  2012-11-19 14:23:19.025 [main] Java: 1.7.0_09-Oracle Corporation
INFO  2012-11-19 14:23:19.025 [main] OS: Windows 7 x86 6.1
INFO  2012-11-19 14:23:19.041 [main] Encoding: UTF-8
INFO  2012-11-19 14:23:19.041 [main] Memory: 742 MB
INFO  2012-11-19 14:23:19.041 [main]
INFO  2012-11-19 14:23:19.041 [main] Working directory: C:\Program Files (x86)\PS3 Media Server
INFO  2012-11-19 14:23:19.041 [main] Temp directory: C:\Users\Tor\AppData\Local\Temp\ps3mediaserver
INFO  2012-11-19 14:23:19.041 [main] Logging config file: C:\Program Files (x86)\PS3 Media Server\logback.xml
INFO  2012-11-19 14:23:19.041 [main] debug.log: C:\Program Files (x86)\PS3 Media Server\debug.log
INFO  2012-11-19 14:23:19.041 [main]
INFO  2012-11-19 14:23:19.041 [main] Profile directory: C:\ProgramData\PMS
INFO  2012-11-19 14:23:19.041 [main] Profile path: C:\ProgramData\PMS\PMS.conf
INFO  2012-11-19 14:23:19.041 [main] Profile permissions: rw
INFO  2012-11-19 14:23:19.041 [main] Profile name: tor-desktop
INFO  2012-11-19 14:23:19.041 [main]
INFO  2012-11-19 14:23:19.041 [main] Loading MediaInfo library
INFO  2012-11-19 14:23:19.166 [main] Loaded MediaInfoLib - v0.7.60
INFO  2012-11-19 14:23:19.166 [main] Loading renderer configurations from C:\Program Files (x86)\PS3 Media Server\renderers
INFO  2012-11-19 14:23:19.166 [main] Loading configuration file: AirPlayer.conf
INFO  2012-11-19 14:23:19.166 [main] Loading configuration file: Android.conf
INFO  2012-11-19 14:23:19.166 [main] Loading configuration file: Bravia4500.conf
INFO  2012-11-19 14:23:19.166 [main] Loading configuration file: Bravia5500.conf
INFO  2012-11-19 14:23:19.166 [main] Loading configuration file: BraviaEX.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: DirecTVHR.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: DLinkDSM510.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: FreeboxHD.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: FreecomMusicPal.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: iPad-iPhone.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: Kuro.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: LGST600.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: N900.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: OPPOBDP83.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: OPPOBDP93.conf
INFO  2012-11-19 14:23:19.181 [main] Loading configuration file: Panasonic.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: Philips.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: PhilipsPFL.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: PopcornHour.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: PS3.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: Realtek.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: Samsung-SMT-G7400.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: SamsungAllShare.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: SamsungWiseLink.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: Showtime3.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: SMP-N100.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: SonyBluray.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: Streamium.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: WDTVLive.conf
INFO  2012-11-19 14:23:19.197 [main] Loading configuration file: WMP.conf
INFO  2012-11-19 14:23:19.212 [main] Loading configuration file: XBMC.conf
INFO  2012-11-19 14:23:19.212 [main] Loading configuration file: XBOX360.conf
INFO  2012-11-19 14:23:19.212 [main] Loading configuration file: YamahaRXA1010.conf
INFO  2012-11-19 14:23:19.212 [main] Loading configuration file: YamahaRXV671.conf
INFO  2012-11-19 14:23:19.212 [main] Checking MPlayer font cache. It can take a minute or so.
DEBUG 2012-11-19 14:23:19.212 [main] launching: win32/mplayer.exe
DEBUG 2012-11-19 14:23:19.290 [main] launching: win32/mplayer.exe
INFO  2012-11-19 14:23:19.369 [main] Done!
INFO  2012-11-19 14:23:19.369 [main] Found VideoLAN version 2.0.3 at: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-19 14:23:19.369 [main] Searching for plugins in C:\Program Files (x86)\PS3 Media Server\plugins
INFO  2012-11-19 14:23:19.369 [main] No plugins found
INFO  2012-11-19 14:23:19.369 [main] Transcoder profile AviSynth/FFmpeg will not be used because AviSynth was not found
INFO  2012-11-19 14:23:19.369 [main] Registering transcoding engine: FFmpeg Audio
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: MEncoder
INFO  2012-11-19 14:23:19.385 [main] Transcoder profile AviSynth/MEncoder will not be used because AviSynth was not found
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: FFmpeg
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: MPlayer Audio
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: FFmpeg Web Video
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: MEncoder Web
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: MPlayer Video Dump
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: MPlayer Web
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: tsMuxeR
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: Audio High Fidelity
DEBUG 2012-11-19 14:23:19.385 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 14:23:19.385 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 14:23:19.385 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 14:23:19.385 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: VLC Audio Streaming
DEBUG 2012-11-19 14:23:19.385 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 14:23:19.385 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 14:23:19.385 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 14:23:19.385 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: VLC Video Streaming
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: FFmpeg DVR-MS Remux
INFO  2012-11-19 14:23:19.385 [main] Registering transcoding engine: dcraw Thumbnailer
INFO  2012-11-19 14:23:19.385 [main] AviSynth is not installed. You cannot use avsmencoder as a transcoding engine.
INFO  2012-11-19 14:23:19.447 [main] Using address /192.168.1.6 found on network interface: name:eth3 (Realtek PCIe GBE Family Controller)
INFO  2012-11-19 14:23:19.447 [main] Created socket: /192.168.1.6:5001
INFO  2012-11-19 14:23:19.494 [main] Checking shared folder: D:\Film\Dokumentarer
INFO  2012-11-19 14:23:19.494 [main] Checking shared folder: D:\Film\Serier
INFO  2012-11-19 14:23:19.494 [main] Checking shared folder: D:\Film\Spillefilm
DEBUG 2012-11-19 14:23:19.510 [main] Sending ALIVE...
INFO  2012-11-19 14:23:19.525 [main] Using the following UUID configured in PMS.conf: a6e31139-e31e-3c85-84c7-a3be1bb7300f
INFO  2012-11-19 14:23:24.417 [New I/O server worker #1-1] No IP filter specified, access granted to /192.168.1.7
INFO  2012-11-19 14:23:24.424 [New I/O server worker #1-1] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:24.457 [New I/O server worker #1-1] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:24.471 [New I/O server worker #1-2] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:24.489 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:24.494 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:24.499 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:25.496 [main] The server should now appear on your renderer
DEBUG 2012-11-19 14:23:35.512 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-19 14:23:43.219 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:43.235 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:43.235 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:46.916 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:53.032 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:23:56.136 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
DEBUG 2012-11-19 14:24:00.145 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-19 14:24:01.518 [New I/O server worker #1-4] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: GStreamer neonhttpsrc, icy-metadata: 1, TE: trailers
INFO  2012-11-19 14:24:01.523 [StartPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\Game of Thrones\Season 2\Game.of.Thrones.S02E08.HDTV.x264-ASAP.mp4
INFO  2012-11-19 14:24:02.249 [New I/O server worker #1-5] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: GStreamer neonhttpsrc, icy-metadata: 1, TE: trailers
INFO  2012-11-19 14:24:06.598 [StopPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\Game of Thrones\Season 2\Game.of.Thrones.S02E08.HDTV.x264-ASAP.mp4
INFO  2012-11-19 14:24:07.004 [New I/O server worker #1-6] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: GStreamer neonhttpsrc, icy-metadata: 1, TE: trailers
INFO  2012-11-19 14:24:07.004 [StartPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\Game of Thrones\Season 2\Game.of.Thrones.S02E08.HDTV.x264-ASAP.mp4
DEBUG 2012-11-19 14:27:04.876 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 14:30:07.990 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 14:33:11.467 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 14:36:16.127 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-19 14:38:43.243 [New I/O server worker #1-7] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
DEBUG 2012-11-19 14:38:43.243 [New I/O server worker #1-7] Caught exception
java.lang.NullPointerException: null
   at net.pms.network.RequestV2.answer(RequestV2.java:707) ~[pms.jar:na]
   at net.pms.network.RequestHandlerV2.writeResponse(RequestHandlerV2.java:301) ~[pms.jar:na]
   at net.pms.network.RequestHandlerV2.messageReceived(RequestHandlerV2.java:256) ~[pms.jar:na]
   at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:149) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(HttpChunkAggregator.java:116) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:302) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.unfoldAndFireMessageReceived(ReplayingDecoder.java:527) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:506) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:443) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:351) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:282) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:202) ~[pms.jar:na]
   at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.7.0_09]
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.7.0_09]
   at java.lang.Thread.run(Unknown Source) [na:1.7.0_09]
INFO  2012-11-19 14:38:48.703 [StopPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\Game of Thrones\Season 2\Game.of.Thrones.S02E08.HDTV.x264-ASAP.mp4
INFO  2012-11-19 14:38:59.654 [New I/O server worker #1-8] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:38:59.654 [New I/O server worker #1-8] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:38:59.670 [New I/O server worker #1-1] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:38:59.701 [New I/O server worker #1-2] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:38:59.717 [New I/O server worker #1-2] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:38:59.717 [New I/O server worker #1-2] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:39:01.105 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:39:01.121 [New I/O server worker #1-3] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:39:01.136 [New I/O server worker #1-4] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:39:01.168 [New I/O server worker #1-5] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:39:01.168 [New I/O server worker #1-5] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:39:01.168 [New I/O server worker #1-5] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
DEBUG 2012-11-19 14:39:20.293 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-19 14:41:01.462 [UPNPHelper] No IP filter specified, access granted to /192.168.1.6
INFO  2012-11-19 14:41:01.930 [pool-11-thread-1] Checking IP: 192.168.1.6 for WMP
INFO  2012-11-19 14:41:03.802 [pool-11-thread-1] Renderer WMP found on this address: 192.168.1.6
DEBUG 2012-11-19 14:41:03.802 [pool-11-thread-1] Starting ping -n 3 -l 64000 192.168.1.6
DEBUG 2012-11-19 14:41:05.814 [SpeedStats Failsafe] Stopping process: ping-0
DEBUG 2012-11-19 14:41:05.814 [pool-11-thread-1] Could not parse time from "64000 time<1"
DEBUG 2012-11-19 14:41:05.814 [pool-11-thread-1] Could not parse time from "64000 time<1"
DEBUG 2012-11-19 14:42:23.486 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-19 14:44:39.621 [New I/O server worker #1-8] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:44:39.636 [New I/O server worker #1-8] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:44:39.652 [New I/O server worker #1-1] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:44:39.683 [New I/O server worker #1-2] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:44:39.683 [New I/O server worker #1-2] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
INFO  2012-11-19 14:44:39.683 [New I/O server worker #1-2] Media renderer was not recognized. Possible identifying HTTP headers: User-Agent: AwoX/1.1 UPnP/1.0 DLNADOC/1.50
DEBUG 2012-11-19 14:45:27.929 [UPNP-AliveMessageSender] Sending ALIVE...
Jarl
 
Posts: 7
Joined: Mon Nov 19, 2012 10:27 am
Top

Re: Samsung Galaxy Note 10.1

Postby C4rtm4N » Mon Nov 19, 2012 12:08 pm

Here you go Raptor399

Code: Select all
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Opened request handler on socket /192.168.1.80:40836
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Request: HTTP/1.1 : SUBSCRIBE : upnp/event/content_directory
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Matched media renderer "Samsung AllShare" based on address /192.168.1.80
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Received on socket: Connection: close
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Received on socket: HOST: 192.168.1.253:5001
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Received on socket: SID: uuid:9463960d-5762-3036-xxxxxxxxxxxxxxxxxxxx
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Received on socket: TIMEOUT: Second-300
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Received on socket: USER-AGENT: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Recognized media renderer Samsung AllShare
TRACE 2012-11-19 11:00:45.862 [New I/O server worker #1-4] HTTP: upnp/event/content_directory / 0-0
DEBUG 2012-11-19 11:00:45.862 [New I/O server worker #1-4] Caught exception
java.lang.NullPointerException: null
   at net.pms.network.RequestV2.answer(RequestV2.java:707) ~[pms.jar:na]
   at net.pms.network.RequestHandlerV2.writeResponse(RequestHandlerV2.java:301) ~[pms.jar:na]
   at net.pms.network.RequestHandlerV2.messageReceived(RequestHandlerV2.java:256) ~[pms.jar:na]
   at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:149) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(HttpChunkAggregator.java:116) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:302) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.unfoldAndFireMessageReceived(ReplayingDecoder.java:527) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:506) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:443) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:351) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:282) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:202) ~[pms.jar:na]
   at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.7.0_09]
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.7.0_09]
   at java.lang.Thread.run(Unknown Source) [na:1.7.0_09]


Interestingly WMP also cannot browse the folders via PMS although there's no error returned

Thanks
C4rtm4N
 
Posts: 4
Joined: Wed Nov 14, 2012 2:34 pm
Top

Re: Server drops out for a few seconds

Postby Jarl » Mon Nov 19, 2012 9:30 pm

Looking at the log I couldn't help but consider that the bug might have something to do with automatic detection, but disabling automatic detection hasn't worked as a work-around.

Debug log with automatic detection disabled:
Code: Select all
INFO  2012-11-19 21:10:16.777 [main] Starting PS3 Media Server 1.72.0
INFO  2012-11-19 21:10:16.792 [main] by shagrath / 2008-2012
INFO  2012-11-19 21:10:16.792 [main] http://ps3mediaserver.org
INFO  2012-11-19 21:10:16.792 [main] https://github.com/ps3mediaserver/ps3mediaserver
INFO  2012-11-19 21:10:16.792 [main]
INFO  2012-11-19 21:10:16.792 [main] Build: d9fd0a44c (2012-11-18)
INFO  2012-11-19 21:10:16.792 [main] Java: 1.7.0_09-Oracle Corporation
INFO  2012-11-19 21:10:16.792 [main] OS: Windows 7 x86 6.1
INFO  2012-11-19 21:10:16.792 [main] Encoding: UTF-8
INFO  2012-11-19 21:10:16.792 [main] Memory: 742 MB
INFO  2012-11-19 21:10:16.792 [main]
INFO  2012-11-19 21:10:16.792 [main] Working directory: C:\Program Files (x86)\PS3 Media Server
INFO  2012-11-19 21:10:16.808 [main] Temp directory: C:\Users\Tor\AppData\Local\Temp\ps3mediaserver
INFO  2012-11-19 21:10:16.808 [main] Logging config file: C:\Program Files (x86)\PS3 Media Server\logback.xml
INFO  2012-11-19 21:10:16.808 [main] debug.log: C:\Program Files (x86)\PS3 Media Server\debug.log
INFO  2012-11-19 21:10:16.808 [main]
INFO  2012-11-19 21:10:16.808 [main] Profile directory: C:\ProgramData\PMS
INFO  2012-11-19 21:10:16.808 [main] Profile path: C:\ProgramData\PMS\PMS.conf
INFO  2012-11-19 21:10:16.808 [main] Profile permissions: rw
INFO  2012-11-19 21:10:16.808 [main] Profile name: tor-desktop
INFO  2012-11-19 21:10:16.808 [main]
INFO  2012-11-19 21:10:16.808 [main] Loading MediaInfo library
INFO  2012-11-19 21:10:16.917 [main] Loaded MediaInfoLib - v0.7.60
INFO  2012-11-19 21:10:16.917 [main] Loading renderer configurations from C:\Program Files (x86)\PS3 Media Server\renderers
INFO  2012-11-19 21:10:16.917 [main] Loading configuration file: AirPlayer.conf
INFO  2012-11-19 21:10:16.917 [main] Loading configuration file: Android.conf
INFO  2012-11-19 21:10:16.917 [main] Loading configuration file: Bravia4500.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: Bravia5500.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: BraviaEX.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: DirecTVHR.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: DLinkDSM510.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: FreeboxHD.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: FreecomMusicPal.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: iPad-iPhone.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: Kuro.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: LGST600.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: N900.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: OPPOBDP83.conf
INFO  2012-11-19 21:10:16.933 [main] Loading configuration file: OPPOBDP93.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: Panasonic.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: Philips.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: PhilipsPFL.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: PopcornHour.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: PS3.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: Realtek.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: Samsung-SMT-G7400.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: SamsungAllShare.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: SamsungWiseLink.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: Showtime3.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: SMP-N100.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: SonyBluray.conf
INFO  2012-11-19 21:10:16.948 [main] Loading configuration file: Streamium.conf
INFO  2012-11-19 21:10:16.964 [main] Loading configuration file: WDTVLive.conf
INFO  2012-11-19 21:10:16.964 [main] Loading configuration file: WMP.conf
INFO  2012-11-19 21:10:16.964 [main] Loading configuration file: XBMC.conf
INFO  2012-11-19 21:10:16.964 [main] Loading configuration file: XBOX360.conf
INFO  2012-11-19 21:10:16.964 [main] Loading configuration file: YamahaRXA1010.conf
INFO  2012-11-19 21:10:16.964 [main] Loading configuration file: YamahaRXV671.conf
INFO  2012-11-19 21:10:16.964 [main] Checking MPlayer font cache. It can take a minute or so.
DEBUG 2012-11-19 21:10:16.964 [main] launching: win32/mplayer.exe
DEBUG 2012-11-19 21:10:17.042 [main] launching: win32/mplayer.exe
INFO  2012-11-19 21:10:17.121 [main] Done!
INFO  2012-11-19 21:10:17.121 [main] Found VideoLAN version 2.0.3 at: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-19 21:10:17.121 [main] Searching for plugins in C:\Program Files (x86)\PS3 Media Server\plugins
INFO  2012-11-19 21:10:17.121 [main] No plugins found
INFO  2012-11-19 21:10:17.121 [main] Transcoder profile AviSynth/FFmpeg will not be used because AviSynth was not found
INFO  2012-11-19 21:10:17.121 [main] Registering transcoding engine: FFmpeg Audio
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: MEncoder
INFO  2012-11-19 21:10:17.136 [main] Transcoder profile AviSynth/MEncoder will not be used because AviSynth was not found
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: FFmpeg
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: MPlayer Audio
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: FFmpeg Web Video
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: MEncoder Web
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: MPlayer Video Dump
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: MPlayer Web
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: tsMuxeR
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: Audio High Fidelity
DEBUG 2012-11-19 21:10:17.136 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 21:10:17.136 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 21:10:17.136 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 21:10:17.136 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: VLC Audio Streaming
DEBUG 2012-11-19 21:10:17.136 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 21:10:17.136 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 21:10:17.136 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-19 21:10:17.136 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: VLC Video Streaming
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: FFmpeg DVR-MS Remux
INFO  2012-11-19 21:10:17.136 [main] Registering transcoding engine: dcraw Thumbnailer
INFO  2012-11-19 21:10:17.136 [main] AviSynth is not installed. You cannot use avsmencoder as a transcoding engine.
INFO  2012-11-19 21:10:17.199 [main] Using address /192.168.1.6 found on network interface: name:eth3 (Realtek PCIe GBE Family Controller)
INFO  2012-11-19 21:10:17.199 [main] Created socket: /192.168.1.6:5001
INFO  2012-11-19 21:10:17.246 [main] Checking shared folder: D:\Film\Dokumentarer
INFO  2012-11-19 21:10:17.246 [main] Checking shared folder: D:\Film\Serier
INFO  2012-11-19 21:10:17.246 [main] Checking shared folder: D:\Film\Spillefilm
DEBUG 2012-11-19 21:10:17.261 [main] Sending ALIVE...
INFO  2012-11-19 21:10:17.277 [main] Using the following UUID configured in PMS.conf: a6e31139-e31e-3c85-84c7-a3be1bb7300f
INFO  2012-11-19 21:10:18.131 [New I/O server worker #1-1] No IP filter specified, access granted to /192.168.1.7
INFO  2012-11-19 21:10:18.138 [pool-7-thread-1] Checking IP: 192.168.1.7 for Playstation 3
INFO  2012-11-19 21:10:21.230 [main] The server should now appear on your renderer
INFO  2012-11-19 21:10:22.774 [pool-7-thread-1] Renderer Playstation 3 found on this address: 192.168.1.7
DEBUG 2012-11-19 21:10:22.774 [pool-7-thread-1] Starting ping -n 3 -l 64000 192.168.1.7
DEBUG 2012-11-19 21:10:24.787 [SpeedStats Failsafe] Stopping process: ping-0
INFO  2012-11-19 21:10:24.787 [pool-7-thread-1] Address /192.168.1.7 has an estimated network speed of: 73 Mb/s
DEBUG 2012-11-19 21:10:31.245 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-19 21:10:52.378 [StartPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\BBC - Planet Earth\BBC.Planet.Earth.1of5.From.Pole.to.Pole.XviD.MP3.www.MVGroup.org.avi
DEBUG 2012-11-19 21:10:55.576 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 21:14:00.544 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-19 21:16:33.403 [UPNPHelper] No IP filter specified, access granted to /192.168.1.6
DEBUG 2012-11-19 21:17:05.259 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 21:20:08.980 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 21:23:14.584 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 21:25:21.038 [New I/O server worker #1-1] Caught exception
java.lang.NullPointerException: null
   at net.pms.network.RequestV2.answer(RequestV2.java:707) ~[pms.jar:na]
   at net.pms.network.RequestHandlerV2.writeResponse(RequestHandlerV2.java:301) ~[pms.jar:na]
   at net.pms.network.RequestHandlerV2.messageReceived(RequestHandlerV2.java:256) ~[pms.jar:na]
   at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:149) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(HttpChunkAggregator.java:116) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:302) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.unfoldAndFireMessageReceived(ReplayingDecoder.java:527) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:506) ~[pms.jar:na]
   at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:443) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274) ~[pms.jar:na]
   at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:351) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:282) ~[pms.jar:na]
   at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:202) ~[pms.jar:na]
   at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.7.0_09]
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.7.0_09]
   at java.lang.Thread.run(Unknown Source) [na:1.7.0_09]
INFO  2012-11-19 21:25:26.264 [StopPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\BBC - Planet Earth\BBC.Planet.Earth.1of5.From.Pole.to.Pole.XviD.MP3.www.MVGroup.org.avi
                                                                                                                                                                                             DEBUG 2012-11-19 21:12:28.035 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 21:15:32.213 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 21:18:34.855 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 21:21:41.107 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-19 21:24:45.615 [UPNP-AliveMessageSender] Sending ALIVE...
Jarl
 
Posts: 7
Joined: Mon Nov 19, 2012 10:27 am
Top

Re: Lost connection/NPE with some renderers

Postby Raptor399 » Tue Nov 20, 2012 12:29 am

Thanks for posting the logs.

It turns out that RequestV2.java was expecting a soap action in the subscribe request. The logs show this isn't present, hence the NullPointerException. Incidentally, the same code in Request.java was already checking for a null soapaction...

Anyway, fix committed.

If you need a workaround, either disable "HTTP Engine V2" in the General Configuration tab, or get yourself a snapshot build.
Raptor399
Project Member
 
Posts: 1688
Joined: Thu Mar 10, 2011 12:06 am
Top

Re: Lost connection/NPE with some renderers

Postby Jarl » Tue Nov 20, 2012 5:30 pm

I've just tried disabling HTTP Engine V2 and the problem persists. Yes, the NullPointerException is squealed (i.e. not in the trace), but the behavior is otherwise exactly as I described before.

A new debug log:
Code: Select all
INFO  2012-11-20 17:11:28.708 [main] Starting PS3 Media Server 1.72.0
INFO  2012-11-20 17:11:28.715 [main] by shagrath / 2008-2012
INFO  2012-11-20 17:11:28.717 [main] http://ps3mediaserver.org
INFO  2012-11-20 17:11:28.718 [main] https://github.com/ps3mediaserver/ps3mediaserver
INFO  2012-11-20 17:11:28.718 [main]
INFO  2012-11-20 17:11:28.719 [main] Build: d9fd0a44c (2012-11-18)
INFO  2012-11-20 17:11:28.721 [main] Java: 1.7.0_09-Oracle Corporation
INFO  2012-11-20 17:11:28.780 [main] OS: Windows 7 x86 6.1
INFO  2012-11-20 17:11:28.782 [main] Encoding: UTF-8
INFO  2012-11-20 17:11:28.783 [main] Memory: 742 MB
INFO  2012-11-20 17:11:28.783 [main]
INFO  2012-11-20 17:11:28.783 [main] Working directory: C:\Program Files (x86)\PS3 Media Server
INFO  2012-11-20 17:11:28.789 [main] Temp directory: C:\Users\Tor\AppData\Local\Temp\ps3mediaserver
INFO  2012-11-20 17:11:28.790 [main] Logging config file: C:\Program Files (x86)\PS3 Media Server\logback.xml
INFO  2012-11-20 17:11:28.790 [main] debug.log: C:\Program Files (x86)\PS3 Media Server\debug.log
INFO  2012-11-20 17:11:28.791 [main]
INFO  2012-11-20 17:11:28.791 [main] Profile directory: C:\ProgramData\PMS
INFO  2012-11-20 17:11:28.791 [main] Profile path: C:\ProgramData\PMS\PMS.conf
INFO  2012-11-20 17:11:28.792 [main] Profile permissions: rw
INFO  2012-11-20 17:11:28.793 [main] Profile name: tor-desktop
INFO  2012-11-20 17:11:28.793 [main]
INFO  2012-11-20 17:11:28.796 [main] Loading MediaInfo library
INFO  2012-11-20 17:11:28.847 [main] Loaded MediaInfoLib - v0.7.60
INFO  2012-11-20 17:11:28.852 [main] Loading renderer configurations from C:\Program Files (x86)\PS3 Media Server\renderers
INFO  2012-11-20 17:11:28.853 [main] Loading configuration file: AirPlayer.conf
INFO  2012-11-20 17:11:28.856 [main] Loading configuration file: Android.conf
INFO  2012-11-20 17:11:28.857 [main] Loading configuration file: Bravia4500.conf
INFO  2012-11-20 17:11:28.859 [main] Loading configuration file: Bravia5500.conf
INFO  2012-11-20 17:11:28.860 [main] Loading configuration file: BraviaEX.conf
INFO  2012-11-20 17:11:28.863 [main] Loading configuration file: DirecTVHR.conf
INFO  2012-11-20 17:11:28.864 [main] Loading configuration file: DLinkDSM510.conf
INFO  2012-11-20 17:11:28.866 [main] Loading configuration file: FreeboxHD.conf
INFO  2012-11-20 17:11:28.866 [main] Loading configuration file: FreecomMusicPal.conf
INFO  2012-11-20 17:11:28.867 [main] Loading configuration file: iPad-iPhone.conf
INFO  2012-11-20 17:11:28.869 [main] Loading configuration file: Kuro.conf
INFO  2012-11-20 17:11:28.870 [main] Loading configuration file: LGST600.conf
INFO  2012-11-20 17:11:28.872 [main] Loading configuration file: N900.conf
INFO  2012-11-20 17:11:28.873 [main] Loading configuration file: OPPOBDP83.conf
INFO  2012-11-20 17:11:28.874 [main] Loading configuration file: OPPOBDP93.conf
INFO  2012-11-20 17:11:28.875 [main] Loading configuration file: Panasonic.conf
INFO  2012-11-20 17:11:28.876 [main] Loading configuration file: Philips.conf
INFO  2012-11-20 17:11:28.877 [main] Loading configuration file: PhilipsPFL.conf
INFO  2012-11-20 17:11:28.880 [main] Loading configuration file: PopcornHour.conf
INFO  2012-11-20 17:11:28.880 [main] Loading configuration file: PS3.conf
INFO  2012-11-20 17:11:28.882 [main] Loading configuration file: Realtek.conf
INFO  2012-11-20 17:11:28.883 [main] Loading configuration file: Samsung-SMT-G7400.conf
INFO  2012-11-20 17:11:28.885 [main] Loading configuration file: SamsungAllShare.conf
INFO  2012-11-20 17:11:28.886 [main] Loading configuration file: SamsungWiseLink.conf
INFO  2012-11-20 17:11:28.887 [main] Loading configuration file: Showtime3.conf
INFO  2012-11-20 17:11:28.888 [main] Loading configuration file: SMP-N100.conf
INFO  2012-11-20 17:11:28.889 [main] Loading configuration file: SonyBluray.conf
INFO  2012-11-20 17:11:28.890 [main] Loading configuration file: Streamium.conf
INFO  2012-11-20 17:11:28.891 [main] Loading configuration file: WDTVLive.conf
INFO  2012-11-20 17:11:28.892 [main] Loading configuration file: WMP.conf
INFO  2012-11-20 17:11:28.893 [main] Loading configuration file: XBMC.conf
INFO  2012-11-20 17:11:28.899 [main] Loading configuration file: XBOX360.conf
INFO  2012-11-20 17:11:28.900 [main] Loading configuration file: YamahaRXA1010.conf
INFO  2012-11-20 17:11:28.901 [main] Loading configuration file: YamahaRXV671.conf
INFO  2012-11-20 17:11:28.902 [main] Checking MPlayer font cache. It can take a minute or so.
DEBUG 2012-11-20 17:11:28.902 [main] launching: win32/mplayer.exe
DEBUG 2012-11-20 17:11:28.970 [main] launching: win32/mplayer.exe
INFO  2012-11-20 17:11:29.049 [main] Done!
INFO  2012-11-20 17:11:29.049 [main] Found VideoLAN version 2.0.3 at: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-20 17:11:29.049 [main] Searching for plugins in C:\Program Files (x86)\PS3 Media Server\plugins
INFO  2012-11-20 17:11:29.049 [main] No plugins found
INFO  2012-11-20 17:11:29.049 [main] Transcoder profile AviSynth/FFmpeg will not be used because AviSynth was not found
INFO  2012-11-20 17:11:29.049 [main] Registering transcoding engine: FFmpeg Audio
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: MEncoder
INFO  2012-11-20 17:11:29.065 [main] Transcoder profile AviSynth/MEncoder will not be used because AviSynth was not found
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: FFmpeg
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: MPlayer Audio
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: FFmpeg Web Video
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: MEncoder Web
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: MPlayer Video Dump
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: MPlayer Web
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: tsMuxeR
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: Audio High Fidelity
DEBUG 2012-11-20 17:11:29.065 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-20 17:11:29.065 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-20 17:11:29.065 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-20 17:11:29.065 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: VLC Audio Streaming
DEBUG 2012-11-20 17:11:29.065 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-20 17:11:29.065 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-20 17:11:29.065 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
DEBUG 2012-11-20 17:11:29.065 [main] Found VLC version 2.0.3 in Windows Registry: C:\Program Files (x86)\VideoLAN\VLC\vlc.exe
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: VLC Video Streaming
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: FFmpeg DVR-MS Remux
INFO  2012-11-20 17:11:29.065 [main] Registering transcoding engine: dcraw Thumbnailer
INFO  2012-11-20 17:11:29.065 [main] AviSynth is not installed. You cannot use avsmencoder as a transcoding engine.
INFO  2012-11-20 17:11:29.112 [main] Using address /192.168.1.6 found on network interface: name:eth3 (Realtek PCIe GBE Family Controller)
INFO  2012-11-20 17:11:29.112 [main] Created socket: /192.168.1.6:5001
INFO  2012-11-20 17:11:29.112 [HTTP Server] Starting DLNA Server on host 192.168.1.6 and port 5001...
INFO  2012-11-20 17:11:29.127 [main] Checking shared folder: D:\Film\Dokumentarer
INFO  2012-11-20 17:11:29.127 [main] Checking shared folder: D:\Film\Serier
INFO  2012-11-20 17:11:29.127 [main] Checking shared folder: D:\Film\Spillefilm
DEBUG 2012-11-20 17:11:29.159 [main] Sending ALIVE...
INFO  2012-11-20 17:11:29.174 [main] Using the following UUID configured in PMS.conf: a6e31139-e31e-3c85-84c7-a3be1bb7300f
INFO  2012-11-20 17:11:34.418 [main] The server should now appear on your renderer
DEBUG 2012-11-20 17:11:44.432 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-20 17:11:44.665 [background-task-0] singleton task restart started
DEBUG 2012-11-20 17:11:44.665 [background-task-0-restart(0)] task started
INFO  2012-11-20 17:11:44.665 [background-task-0-restart(0)] Sending BYEBYE...
INFO  2012-11-20 17:11:46.252 [HTTP Server] No IP filter specified, access granted to /192.168.1.7
INFO  2012-11-20 17:11:46.271 [pool-5-thread-1] Checking IP: 192.168.1.7 for Playstation 3
INFO  2012-11-20 17:11:48.755 [background-task-0-restart(0)] Stopping server on host 192.168.1.6 and port 5001...
DEBUG 2012-11-20 17:11:49.091 [UPNP-AliveMessageSender] Error while sending periodic alive message: null
INFO  2012-11-20 17:11:49.779 [background-task-0-restart(0)] Using address /192.168.1.6 found on network interface: name:eth3 (Realtek PCIe GBE Family Controller)
INFO  2012-11-20 17:11:49.779 [background-task-0-restart(0)] Created socket: /192.168.1.6:5001
DEBUG 2012-11-20 17:11:49.779 [background-task-0-restart(0)] Sending ALIVE...
INFO  2012-11-20 17:11:49.779 [HTTP Server] Starting DLNA Server on host 192.168.1.6 and port 5001...
INFO  2012-11-20 17:11:50.881 [pool-5-thread-1] Renderer Playstation 3 found on this address: 192.168.1.7
DEBUG 2012-11-20 17:11:50.884 [pool-5-thread-1] Starting ping -n 3 -l 64000 192.168.1.7
INFO  2012-11-20 17:11:51.644 [Request Handler] Checking shared folder: D:\Film\Dokumentarer
INFO  2012-11-20 17:11:51.645 [Request Handler] Checking shared folder: D:\Film\Serier
INFO  2012-11-20 17:11:51.645 [Request Handler] Checking shared folder: D:\Film\Spillefilm
DEBUG 2012-11-20 17:11:52.884 [SpeedStats Failsafe] Stopping process: ping-0
INFO  2012-11-20 17:11:52.885 [pool-5-thread-1] Address /192.168.1.7 has an estimated network speed of: 73 Mb/s
DEBUG 2012-11-20 17:11:55.213 [background-task-0-restart(0)] task ended
DEBUG 2012-11-20 17:11:59.100 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-20 17:12:16.881 [StartPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\BBC - Planet Earth\BBC.Planet.Earth.1of5.From.Pole.to.Pole.XviD.MP3.www.MVGroup.org.avi
DEBUG 2012-11-20 17:12:24.883 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-20 17:12:56.298 [UPNPHelper] No IP filter specified, access granted to /192.168.1.6
DEBUG 2012-11-20 17:15:29.350 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-20 17:18:34.297 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-20 17:21:38.679 [UPNP-AliveMessageSender] Sending ALIVE...
DEBUG 2012-11-20 17:24:42.510 [UPNP-AliveMessageSender] Sending ALIVE...
INFO  2012-11-20 17:26:57.667 [StopPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\BBC - Planet Earth\BBC.Planet.Earth.1of5.From.Pole.to.Pole.XviD.MP3.www.MVGroup.org.avi
DEBUG 2012-11-20 17:27:47.291 [UPNP-AliveMessageSender] Sending ALIVE...
Jarl
 
Posts: 7
Joined: Mon Nov 19, 2012 10:27 am
Top

Re: Lost connection/NPE with some renderers

Postby chocolateboy » Tue Nov 20, 2012 5:32 pm

Please don't paste inline logfiles: FAQ: How can I supply details to help diagnose my problem?
chocolateboy
Project Member
 
Posts: 2473
Joined: Wed Sep 16, 2009 10:05 am
Top

Re: Lost connection/NPE with some renderers

Postby Raptor399 » Tue Nov 20, 2012 7:01 pm

Jarl wrote:I've just tried disabling HTTP Engine V2 and the problem persists. Yes, the NullPointerException is squealed (i.e. not in the trace), but the behavior is otherwise exactly as I described before.

A new debug log:
Code: Select all
INFO  2012-11-20 17:12:16.881 [StartPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\BBC - Planet Earth\BBC.Planet.Earth.1of5.From.Pole.to.Pole.XviD.MP3.www.MVGroup.org.avi
...
INFO  2012-11-20 17:26:57.667 [StopPlaying Event] renderer: 192.168.1.7, file: D:\Film\Serier\BBC - Planet Earth\BBC.Planet.Earth.1of5.From.Pole.to.Pole.XviD.MP3.www.MVGroup.org.avi

I take it this is the 14 minutes of play you got when it suddenly stopped?

According to this log, PMS ended up executing StartStopListenerDelegate.stop(). This method is called from only one spot in RequestHandler. Alas this is the finally bit of a long try and the log does not provide any hints as to what was happening.

Please follow the instructions I provided earlier, but use the logger name "net.pms.network.RequestHandler" instead. It should be interesting to see what is handled just prior to the "StopPlaying Event".
Raptor399
Project Member
 
Posts: 1688
Joined: Thu Mar 10, 2011 12:06 am
Top

Re: Lost connection/NPE with some renderers

Postby C4rtm4N » Wed Nov 21, 2012 4:29 pm

Same problem for me still (PMS is detected but simply shows no files) with both the snapshot build and disabling http v2, also no null pointer exception shown any more. Interestingly the PS3 that I tested things on could not find PMS when the snapshot of v1.80 was used & the Note can't find PMS when the PS3 is turned on & version 1.72 is being used.

Here's the new trace with the different logger but this time set to Trace rather than Debug.

One thing I have noticed is that the entry "Multicast socket is on interface: /82.xx.xx.xx" appears. I'm not sure if it's relevant but my server has both an internal and an external IP on the same NIC - I'm forcing it to use the internal IP

Code: Select all
TRACE 2012-11-21 15:34:37.118 [main] Searching network interface for 192.168.1.253
TRACE 2012-11-21 15:34:37.134 [main] Sending message from multicast socket on network interface: name:eth0 (D-Link DGE-528T Gigabit Ethernet Adapter)
TRACE 2012-11-21 15:34:37.134 [main] Multicast socket is on interface: /82.xx.xx.xx
TRACE 2012-11-21 15:34:37.134 [main] Socket Timeout: 0
TRACE 2012-11-21 15:34:37.134 [main] Socket TTL: 32
INFO  2012-11-21 15:34:37.134 [main] Using the following UUID configured in PMS.conf: 9463960d-5762-3036-aaf2-xxxxx
TRACE 2012-11-21 15:34:41.040 [main] Waiting 250 milliseconds...
TRACE 2012-11-21 15:34:41.290 [UPNPHelper] Searching network interface for 192.168.1.253
INFO  2012-11-21 15:34:41.290 [main] The server should now appear on your renderer
INFO  2012-11-21 15:34:51.274 [UPNPHelper] No IP filter specified, access granted to /192.168.1.80
TRACE 2012-11-21 15:34:51.274 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:47749]
DEBUG 2012-11-21 15:34:51.305 [UPNP-AliveMessageSender] Sending ALIVE...
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Sending this reply [192.168.1.80:47749]: HTTP/1.1 200 OK<CRLF>CACHE-CONTROL: max-age=1200<CRLF>DATE: Wed, 21 Nov 2012 15:34:51 GMT<CRLF>LOCATION: http://192.168.1.253:5001/description/fetch<CRLF>SERVER: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0<CRLF>ST: upnp:rootdevice<CRLF>EXT: <CRLF>USN: uuid:9463960d-5762-3036-aaf2-xxxxx::upnp:rootdevice<CRLF>Content-Length: 0<CRLF><CRLF>
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:47749]
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:47749]
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Sending this reply [192.168.1.80:47749]: HTTP/1.1 200 OK<CRLF>CACHE-CONTROL: max-age=1200<CRLF>DATE: Wed, 21 Nov 2012 15:34:51 GMT<CRLF>LOCATION: http://192.168.1.253:5001/description/fetch<CRLF>SERVER: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0<CRLF>ST: urn:schemas-upnp-org:device:MediaServer:1<CRLF>EXT: <CRLF>USN: uuid:9463960d-5762-3036-aaf2-xxxx::urn:schemas-upnp-org:device:MediaServer:1<CRLF>Content-Length: 0<CRLF><CRLF>
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:47749]
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:47749]
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:47749]
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:47749]
TRACE 2012-11-21 15:34:51.305 [UPNP-AliveMessageSender] Searching network interface for 192.168.1.253
TRACE 2012-11-21 15:34:51.305 [UPNP-AliveMessageSender] Sending message from multicast socket on network interface: name:eth0 (D-Link DGE-528T Gigabit Ethernet Adapter)
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:40903]
TRACE 2012-11-21 15:34:51.305 [UPNP-AliveMessageSender] Multicast socket is on interface: /82.xx.xx.xx
TRACE 2012-11-21 15:34:51.305 [UPNP-AliveMessageSender] Socket Timeout: 0
TRACE 2012-11-21 15:34:51.305 [UPNP-AliveMessageSender] Socket TTL: 32
TRACE 2012-11-21 15:34:51.305 [UPNPHelper] Sending this reply [192.168.1.80:40903]: HTTP/1.1 200 OK<CRLF>CACHE-CONTROL: max-age=1200<CRLF>DATE: Wed, 21 Nov 2012 15:34:51 GMT<CRLF>LOCATION: http://192.168.1.253:5001/description/fetch<CRLF>SERVER: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0<CRLF>ST: upnp:rootdevice<CRLF>EXT: <CRLF>USN: uuid:9463960d-5762-3036-aaf2-xxxxx::upnp:rootdevice<CRLF>Content-Length: 0<CRLF><CRLF>
TRACE 2012-11-21 15:34:51.321 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:51.321 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:40903]
TRACE 2012-11-21 15:34:51.321 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:40903]
TRACE 2012-11-21 15:34:51.321 [UPNPHelper] Sending this reply [192.168.1.80:40903]: HTTP/1.1 200 OK<CRLF>CACHE-CONTROL: max-age=1200<CRLF>DATE: Wed, 21 Nov 2012 15:34:51 GMT<CRLF>LOCATION: http://192.168.1.253:5001/description/fetch<CRLF>SERVER: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0<CRLF>ST: urn:schemas-upnp-org:device:MediaServer:1<CRLF>EXT: <CRLF>USN: uuid:9463960d-5762-3036-aaf2-xxxxx::urn:schemas-upnp-org:device:MediaServer:1<CRLF>Content-Length: 0<CRLF><CRLF>
TRACE 2012-11-21 15:34:51.321 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:40903]
TRACE 2012-11-21 15:34:51.321 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:40903]
TRACE 2012-11-21 15:34:51.321 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:40903]
TRACE 2012-11-21 15:34:51.321 [UPNPHelper] Receiving a M-SEARCH from [192.168.1.80:40903]
TRACE 2012-11-21 15:34:51.430 [HTTP Server] Receiving a request from: 192.168.1.80
TRACE 2012-11-21 15:34:51.446 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:3931]
TRACE 2012-11-21 15:34:51.446 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:3931]
TRACE 2012-11-21 15:34:51.446 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:3931]
TRACE 2012-11-21 15:34:51.446 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:2721]
TRACE 2012-11-21 15:34:51.446 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:2217]
TRACE 2012-11-21 15:34:51.446 [Request Handler] Opened request handler on socket Socket[addr=/192.168.1.80,port=42035,localport=5001]
TRACE 2012-11-21 15:34:51.446 [Request Handler] Received on socket: GET /description/fetch HTTP/1.1
TRACE 2012-11-21 15:34:51.446 [Request Handler] Received on socket: User-Agent: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0
TRACE 2012-11-21 15:34:51.477 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:51.477 [Request Handler] Matched media renderer "Samsung AllShare" based on header "User-Agent: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0"
TRACE 2012-11-21 15:34:51.493 [Request Handler] Received on socket: TIMEOUT: 3000
TRACE 2012-11-21 15:34:51.493 [Request Handler] Received on socket: Host: 192.168.1.253:5001
TRACE 2012-11-21 15:34:51.493 [Request Handler] Received on socket: Connection: Keep-Alive
TRACE 2012-11-21 15:34:51.493 [Request Handler] HTTP User-Agent: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0
TRACE 2012-11-21 15:34:51.493 [Request Handler] Recognized media renderer Samsung AllShare
TRACE 2012-11-21 15:34:51.493 [Request Handler] HTTP: description/fetch / 0-0
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket: HTTP/1.1 200 OK
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket: Content-Type: text/xml; charset="utf-8"
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket: Cache-Control: no-cache
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket: Expires: 0
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket: Accept-Ranges: bytes
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket: Connection: keep-alive
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket: Server: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0
TRACE 2012-11-21 15:34:51.493 [Request Handler] Available Content-Length: 2038
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket: Content-Length: 2038
TRACE 2012-11-21 15:34:51.493 [Request Handler] Wrote on socket:
TRACE 2012-11-21 15:34:51.493 [Request Handler] Sending stream: 2038 bytes of description/fetch
TRACE 2012-11-21 15:34:51.493 [Request Handler] Close connection
INFO  2012-11-21 15:34:51.493 [pool-5-thread-1] Checking IP: 192.168.1.80 for Samsung AllShare
TRACE 2012-11-21 15:34:51.540 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:2788]
TRACE 2012-11-21 15:34:51.540 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:2788]
TRACE 2012-11-21 15:34:51.540 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:2788]
TRACE 2012-11-21 15:34:51.540 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:3932]
TRACE 2012-11-21 15:34:51.540 [UPNPHelper] Receiving a NOTIFY from [192.168.1.76:4236]
TRACE 2012-11-21 15:34:51.586 [HTTP Server] Receiving a request from: 192.168.1.80
TRACE 2012-11-21 15:34:51.586 [Request Handler] Opened request handler on socket Socket[addr=/192.168.1.80,port=53949,localport=5001]
TRACE 2012-11-21 15:34:51.586 [Request Handler] Received on socket: GET /UPnP_AV_ContentDirectory_1.0.xml HTTP/1.1
TRACE 2012-11-21 15:34:51.586 [Request Handler] Received on socket: User-Agent: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0
TRACE 2012-11-21 15:34:51.586 [Request Handler] Matched media renderer "Samsung AllShare" based on address /192.168.1.80
TRACE 2012-11-21 15:34:51.586 [Request Handler] Received on socket: TIMEOUT: 3000
TRACE 2012-11-21 15:34:51.586 [Request Handler] Received on socket: Host: 192.168.1.253:5001
TRACE 2012-11-21 15:34:51.586 [Request Handler] Received on socket: Connection: Keep-Alive
TRACE 2012-11-21 15:34:51.586 [Request Handler] Recognized media renderer Samsung AllShare
TRACE 2012-11-21 15:34:51.586 [Request Handler] HTTP: UPnP_AV_ContentDirectory_1.0.xml / 0-0
TRACE 2012-11-21 15:34:51.586 [Request Handler] Wrote on socket: HTTP/1.1 200 OK
TRACE 2012-11-21 15:34:51.586 [Request Handler] Wrote on socket: Content-Type: text/xml; charset="utf-8"
TRACE 2012-11-21 15:34:51.586 [Request Handler] Wrote on socket: Cache-Control: no-cache
TRACE 2012-11-21 15:34:51.586 [Request Handler] Wrote on socket: Expires: 0
TRACE 2012-11-21 15:34:51.602 [Request Handler] Wrote on socket: Accept-Ranges: bytes
TRACE 2012-11-21 15:34:51.602 [Request Handler] Wrote on socket: Connection: keep-alive
TRACE 2012-11-21 15:34:51.602 [Request Handler] Wrote on socket: Server: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0
TRACE 2012-11-21 15:34:51.602 [Request Handler] Available Content-Length: 9050
TRACE 2012-11-21 15:34:51.602 [Request Handler] Wrote on socket: Content-Length: 9050
TRACE 2012-11-21 15:34:51.602 [Request Handler] Wrote on socket:
TRACE 2012-11-21 15:34:51.602 [Request Handler] Sending stream: 9050 bytes of UPnP_AV_ContentDirectory_1.0.xml
TRACE 2012-11-21 15:34:51.602 [Request Handler] Close connection
TRACE 2012-11-21 15:34:51.665 [HTTP Server] Receiving a request from: 192.168.1.80
TRACE 2012-11-21 15:34:51.665 [Request Handler] Opened request handler on socket Socket[addr=/192.168.1.80,port=43673,localport=5001]
TRACE 2012-11-21 15:34:51.665 [Request Handler] Received on socket: GET /UPnP_AV_ConnectionManager_1.0.xml HTTP/1.1
TRACE 2012-11-21 15:34:51.665 [Request Handler] Received on socket: User-Agent: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0
TRACE 2012-11-21 15:34:51.665 [Request Handler] Matched media renderer "Samsung AllShare" based on address /192.168.1.80
TRACE 2012-11-21 15:34:51.665 [Request Handler] Received on socket: TIMEOUT: 3000
TRACE 2012-11-21 15:34:51.665 [Request Handler] Received on socket: Host: 192.168.1.253:5001
TRACE 2012-11-21 15:34:51.665 [Request Handler] Received on socket: Connection: Keep-Alive
TRACE 2012-11-21 15:34:51.665 [Request Handler] Recognized media renderer Samsung AllShare
TRACE 2012-11-21 15:34:51.665 [Request Handler] HTTP: UPnP_AV_ConnectionManager_1.0.xml / 0-0
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket: HTTP/1.1 200 OK
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket: Content-Type: text/xml; charset="utf-8"
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket: Cache-Control: no-cache
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket: Expires: 0
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket: Accept-Ranges: bytes
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket: Connection: keep-alive
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket: Server: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0
TRACE 2012-11-21 15:34:51.665 [Request Handler] Available Content-Length: 6990
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket: Content-Length: 6990
TRACE 2012-11-21 15:34:51.665 [Request Handler] Wrote on socket:
TRACE 2012-11-21 15:34:51.665 [Request Handler] Sending stream: 6990 bytes of UPnP_AV_ConnectionManager_1.0.xml
TRACE 2012-11-21 15:34:51.665 [Request Handler] Close connection
TRACE 2012-11-21 15:34:51.727 [HTTP Server] Receiving a request from: 192.168.1.80
TRACE 2012-11-21 15:34:51.727 [Request Handler] Opened request handler on socket Socket[addr=/192.168.1.80,port=37109,localport=5001]
TRACE 2012-11-21 15:34:51.727 [Request Handler] Received on socket: POST /upnp/control/content_directory HTTP/1.1
TRACE 2012-11-21 15:34:51.727 [Request Handler] Received on socket: USER-AGENT: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0
TRACE 2012-11-21 15:34:51.727 [Request Handler] Matched media renderer "Samsung AllShare" based on address /192.168.1.80
TRACE 2012-11-21 15:34:51.727 [Request Handler] Received on socket: Content-Type: text/xml; charset="utf-8"
TRACE 2012-11-21 15:34:51.727 [Request Handler] Received on socket: HOST: 192.168.1.253:5001
TRACE 2012-11-21 15:34:51.727 [Request Handler] Received on socket: Content-Length: 287
TRACE 2012-11-21 15:34:51.727 [Request Handler] Received on socket: SOAPACTION: "urn:schemas-upnp-org:service:ContentDirectory:1#GetSearchCapabilities"
TRACE 2012-11-21 15:34:51.727 [Request Handler] Received on socket: Connection: close
TRACE 2012-11-21 15:34:51.727 [Request Handler] Recognized media renderer Samsung AllShare
TRACE 2012-11-21 15:34:51.727 [Request Handler] HTTP: upnp/control/content_directory / 0-0
TRACE 2012-11-21 15:34:51.727 [Request Handler] Wrote on socket: HTTP/1.1 200 OK
TRACE 2012-11-21 15:34:51.727 [Request Handler] Wrote on socket: CONTENT-TYPE: text/xml; charset="utf-8"
TRACE 2012-11-21 15:34:51.727 [Request Handler] Wrote on socket: Server: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0
TRACE 2012-11-21 15:34:51.727 [Request Handler] Wrote on socket: Content-Length: 354
TRACE 2012-11-21 15:34:51.727 [Request Handler] Wrote on socket:
TRACE 2012-11-21 15:34:51.727 [Request Handler] Close connection
TRACE 2012-11-21 15:34:51.727 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:51.774 [HTTP Server] Receiving a request from: 192.168.1.80
TRACE 2012-11-21 15:34:51.774 [Request Handler] Opened request handler on socket Socket[addr=/192.168.1.80,port=35535,localport=5001]
TRACE 2012-11-21 15:34:51.774 [Request Handler] Received on socket: SUBSCRIBE /upnp/event/content_directory HTTP/1.1
TRACE 2012-11-21 15:34:51.774 [Request Handler] Received on socket: USER-AGENT: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0
TRACE 2012-11-21 15:34:51.774 [Request Handler] Matched media renderer "Samsung AllShare" based on address /192.168.1.80
TRACE 2012-11-21 15:34:51.774 [Request Handler] Received on socket: HOST: 192.168.1.253:5001
TRACE 2012-11-21 15:34:51.774 [Request Handler] Received on socket: CALLBACK: <http://192.168.1.80:16882/evetSub>
TRACE 2012-11-21 15:34:51.774 [Request Handler] Received on socket: NT: upnp:event
TRACE 2012-11-21 15:34:51.774 [Request Handler] Received on socket: TIMEOUT: Second-300
TRACE 2012-11-21 15:34:51.774 [Request Handler] Received on socket: Connection: close
TRACE 2012-11-21 15:34:51.774 [Request Handler] Recognized media renderer Samsung AllShare
TRACE 2012-11-21 15:34:51.774 [Request Handler] HTTP: upnp/event/content_directory / 0-0
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: HTTP/1.1 200 OK
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: CONTENT-TYPE: text/xml; charset="utf-8"
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: Content-Length: 0
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: Connection: close
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: SID: uuid:9463960d-5762-3036-aaf2-xxxxx
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: Server: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: Timeout: Second-1800
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket:
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: NOTIFY /upnp/event/content_directory HTTP/1.1
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: SID: uuid:9463960d-5762-3036-aaf2-xxxxx
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: SEQ: 0
TRACE 2012-11-21 15:34:51.774 [Request Handler] Wrote on socket: NT: upnp:event
TRACE 2012-11-21 15:34:51.790 [Request Handler] Wrote on socket: NTS: upnp:propchange
TRACE 2012-11-21 15:34:51.790 [Request Handler] Wrote on socket: HOST: 192.168.1.80:16882
TRACE 2012-11-21 15:34:51.790 [Request Handler] Wrote on socket: CONTENT-TYPE: text/xml; charset="utf-8"
TRACE 2012-11-21 15:34:51.790 [Request Handler] Wrote on socket: Server: Windows_2003-x86-5.2, UPnP/1.0, PMS/1.72.0
TRACE 2012-11-21 15:34:51.790 [Request Handler] Wrote on socket: Content-Length: 307
TRACE 2012-11-21 15:34:51.790 [Request Handler] Wrote on socket:
TRACE 2012-11-21 15:34:51.790 [Request Handler] Close connection
TRACE 2012-11-21 15:34:52.227 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:52.274 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:53.118 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:53.602 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:53.743 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:54.539 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:55.321 [UPNPHelper] Receiving a NOTIFY from [192.168.1.253:49318]
TRACE 2012-11-21 15:34:56.102 [pool-5-thread-1] We couldn't get the value based on the canonical name
INFO  2012-11-21 15:34:56.102 [pool-5-thread-1] Renderer Samsung AllShare found on this address: 192.168.1.80
DEBUG 2012-11-21 15:34:56.118 [pool-5-thread-1] Starting ping -n 3 -l 64000 192.168.1.80
TRACE 2012-11-21 15:34:56.149 [Thread-12] Pinging 192.168.1.80 with 64000 bytes of data:
DEBUG 2012-11-21 15:34:58.117 [SpeedStats Failsafe] Stopping process: ping-0
TRACE 2012-11-21 15:34:59.977 [HTTP Server] Receiving a request from: 192.168.1.80
TRACE 2012-11-21 15:34:59.977 [Request Handler] Opened request handler on socket Socket[addr=/192.168.1.80,port=59978,localport=5001]
TRACE 2012-11-21 15:34:59.977 [Request Handler] Received on socket: UNSUBSCRIBE /upnp/event/content_directory HTTP/1.1
TRACE 2012-11-21 15:34:59.977 [Request Handler] Received on socket: USER-AGENT: DLNADOC/1.50 SEC_HHP_"[Tablet]GalaxyNote01"/1.0
TRACE 2012-11-21 15:34:59.977 [Request Handler] Received on socket: HOST: 192.168.1.253:5001
TRACE 2012-11-21 15:34:59.977 [Request Handler] Received on socket: SID: uuid:9463960d-5762-3036-aaf2-xxxxx
TRACE 2012-11-21 15:34:59.992 [Request Handler] Received on socket: Connection: close
TRACE 2012-11-21 15:34:59.992 [Request Handler] Close connection
C4rtm4N
 
Posts: 4
Joined: Wed Nov 14, 2012 2:34 pm
Top

Re: Lost connection/NPE with some renderers

Postby Jarl » Wed Nov 21, 2012 5:19 pm

Raptor399 wrote:I take it this is the 14 minutes of play you got when it suddenly stopped?


You are correct.

I will follow your instructions and upload a log sometime tomorrow.
Jarl
 
Posts: 7
Joined: Mon Nov 19, 2012 10:27 am
Top

Re: Lost connection/NPE with some renderers

Postby Jarl » Wed Nov 21, 2012 7:39 pm

Surprisingly got around to it today.

New debug log:
http://pastebin.com/HJy2kwDG
Jarl
 
Posts: 7
Joined: Mon Nov 19, 2012 10:27 am
Top
PreviousNext
Post a reply

Return to Alternative Media Renderers

Who is online

Users browsing this forum: No registered users and 4 guests

Powered by phpBB® Forum Software © phpBB Group