Avisynth not working properly

[blackstar]

Hi, i installed ps3 media server and i noticed that my avisynth/ffpeg and avisnyth/MEncoder have been disabled. I enabled them and I tried many videos to play on the ps3, but it doesn't load up, just black screen. I have used MEncoder only and it works fine. I also installed Avisynth 2.5.7 and CCCP package. Here is my debug log

[main] TRACE 15:25:02.156 Starting Java PS3 Media Server v1.04
[main] TRACE 15:25:02.156 by shagrath / 2008
[main] TRACE 15:25:02.156 http://ps3mediaserver.blogspot.com
[main] TRACE 15:25:02.156
[main] TRACE 15:25:02.156 Java 1.6.0_03-Sun Microsystems Inc.
[main] TRACE 15:25:02.156 OS Windows XP x86 5.1
[main] TRACE 15:25:02.156 Encoding: Cp1252
[main] TRACE 15:25:02.218 Temp folder: C:\DOCUME~1\Amarpaul\LOCALS~1\Temp\javaps3media
[main] TRACE 15:25:02.718 Found AviSynth plugins dir: C:\Program Files\AviSynth 2.5\plugins
[main] TRACE 15:25:02.718 Found VideoLAN version 0.9.2 at: C:\Program Files\VideoLAN\VLC\vlc.exe
[main] TRACE 15:25:02.718 Registering transcoding engine AviSynth/FFmpeg
[main] TRACE 15:25:02.718 Registering transcoding engine FFmpeg Audio
[main] TRACE 15:25:02.718 Registering transcoding engine MEncoder
[main] TRACE 15:25:02.718 Registering transcoding engine Avisynth/MEncoder
[main] TRACE 15:25:02.718 Registering transcoding engine MPlayer Audio
[main] TRACE 15:25:02.718 Registering transcoding engine MEncoder Web
[main] TRACE 15:25:02.718 Registering transcoding engine MPlayer Video Dump
[main] TRACE 15:25:02.718 Registering transcoding engine MPlayer Web
[main] TRACE 15:25:02.718 Registering transcoding engine TsMuxer
[main] TRACE 15:25:02.718 Registering transcoding engine Audio High Fidelity
[main] TRACE 15:25:02.718 Registering transcoding engine VideoLan Audio Streaming
[main] TRACE 15:25:02.718 Registering transcoding engine VideoLan Video Streaming
[main] TRACE 15:25:02.718 Registering transcoding engine FFmpeg DVR-MS Remux
[main] TRACE 15:25:02.718 Registering transcoding engine Raws Thumbnailer
[main] TRACE 15:25:02.812 Scanning network interface lo / MS TCP Loopback interface
[main] TRACE 15:25:02.812 Scanning network interface eth0 / VMware Virtual Ethernet Adapter for VMnet8
[main] TRACE 15:25:02.812 Scanning network interface eth1 / VMware Virtual Ethernet Adapter for VMnet1
[main] TRACE 15:25:02.812 Scanning network interface eth2 / Hamachi Network Interface #2
[main] TRACE 15:25:02.812 Scanning network interface eth3 / Hamachi Network Interface
[main] TRACE 15:25:02.812 Scanning network interface eth4 / Realtek RTL8168/8111 PCI-E Gigabit Ethernet NIC - Packet Scheduler Miniport
[main] TRACE 15:25:02.812 Using forced address 192.168.1.101
[main] TRACE 15:25:02.828 Created socket: /192.168.1.101:5001
[Thread-15] TRACE 15:25:02.828 Starting DLNA Server on host 192.168.1.101 and port 5001...
[main] TRACE 15:25:02.843 Using following UUID: c39efdcb-df54-3b43-b131-519287120a7a
[Thread-15] TRACE 15:25:03.171 Receiving a request from: 192.168.1.142
[main] TRACE 15:25:03.406 It's ready! You should see the server appears on XMB


I got a high end rig (quad core) and I am running wireless at 50% signal.

[shagrath]

well hard to help
in fact I was talking about the debug.log file (much more detailed), not the basic traces in "Traces" tab

[blackstar]

[Thread-129] TRACE 16:42:32.218 Starting transcode/remux of name of video.avi
[win32/ffmpeg.exe] INFO 16:42:32.234 Starting C:\Program Files\PS3 Media Server\win32\ffmpeg.exe -title dummy -title dummy -i C:\DOCUME~1\Amarpaul\LOCALS~1\Temp\javaps3media\pms-avs-name of video.avi.avs -title dummy -title dummy -vcodec mpeg2video -f vob -acodec ac3 -threads 2 -g 1 -qscale 1 -qmin 2 -ab 384k -threads 4 -muxpreload 0 pipe:
[win32/ffmpeg.exe] INFO 16:42:32.312 Attaching thread: win32/ffmpeg.exe
[Timer-6] DEBUG 16:42:32.312 Buffered Space: 0 bytes
[Thread-128] INFO 16:42:32.375 HTTP: upnp/control/content_directory / 0-0
[Thread-128] DEBUG 16:42:32.375 Wrote on socket: HTTP/1.1 200 OK
[Thread-128] DEBUG 16:42:32.375 Wrote on socket: CONTENT-TYPE: text/xml; charset="utf-8"
[Thread-128] DEBUG 16:42:32.375 Wrote on socket: Server: Windows XP-x86-5.1 UPnP/1.0, PMS
[Thread-128] DEBUG 16:42:32.375 Wrote on socket: Content-Length: 332
[Thread-128] DEBUG 16:42:32.375 Wrote on socket:
[Thread-128] DEBUG 16:42:32.375 Close Connection
[Thread-133] DEBUG 16:42:32.375 Opened handler on socket Socket[addr=/192.168.1.142,port=51317,localport=5001]
[Thread-133] DEBUG 16:42:32.375 Received on socket: POST /upnp/control/content_directory HTTP/1.1
[Thread-133] DEBUG 16:42:32.375 Received on socket: X-AV-Client-Info: av=5.0; cn="Sony Computer Entertainment Inc."; mn="PLAYSTATION 3"; mv="1.0";
[Thread-133] DEBUG 16:42:32.390 Received on socket: Host: 192.168.1.101:5001
[Thread-133] DEBUG 16:42:32.390 Received on socket: User-Agent: UPnP/1.0 DLNADOC/1.50
[Thread-133] DEBUG 16:42:32.390 Received on socket: Content-Length: 915
[Thread-133] DEBUG 16:42:32.390 Received on socket: Content-Type: text/xml; charset="utf-8"
[Thread-133] DEBUG 16:42:32.390 Received on socket: SOAPACTION: "urn:schemas-upnp-org:service:ContentDirectory:1#Browse"
[Thread-133] INFO 16:42:32.593 HTTP: upnp/control/content_directory / 0-0
[Thread-133] DEBUG 16:42:32.593 Wrote on socket: HTTP/1.1 200 OK
[Thread-133] DEBUG 16:42:32.593 Wrote on socket: CONTENT-TYPE: text/xml; charset="utf-8"
[Thread-133] DEBUG 16:42:32.593 Searching for objectId: 0$0$2$0$3$3$1$0 with children option: false
[Thread-133] DEBUG 16:42:32.593 Wrote on socket: Server: Windows XP-x86-5.1 UPnP/1.0, PMS
[Thread-133] DEBUG 16:42:32.593 Wrote on socket: Content-Length: 1083
[Thread-133] DEBUG 16:42:32.593 Wrote on socket:
[Thread-133] DEBUG 16:42:32.593 Close Connection
[Thread-130] DEBUG 16:42:32.703 FFmpeg version SVN-r16596-Sherpya, Copyright (c) 2000-2009 Fabrice Bellard, et al.
[Thread-130] DEBUG 16:42:32.703 libavutil 49.12. 0 / 49.12. 0
[Thread-130] DEBUG 16:42:32.703 libavcodec 52.10. 0 / 52.10. 0
[Thread-130] DEBUG 16:42:32.703 libavformat 52.23. 1 / 52.23. 1
[Thread-130] DEBUG 16:42:32.703 libavdevice 52. 1. 0 / 52. 1. 0
[Thread-130] DEBUG 16:42:32.703 libavfilter 0. 2. 0 / 0. 2. 0
[Thread-130] DEBUG 16:42:32.703 libswscale 0. 6. 1 / 0. 6. 1
[Thread-130] DEBUG 16:42:32.703 libpostproc 51. 2. 0 / 51. 2. 0
[Thread-130] DEBUG 16:42:32.703 built on Jan 14 2009 07:24:48, gcc: 4.2.5 20080919 (prerelease) [Sherpya]
[Timer-6] DEBUG 16:42:33.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:34.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:35.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:36.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:37.312 Buffered Space: 0 bytes
[Thread-129] DEBUG 16:42:38.234 Wrote on socket: Content-Type: video/mpeg
[Thread-129] DEBUG 16:42:38.234 Wrote on socket: Connection: keep-alive
[Thread-129] DEBUG 16:42:38.234 Wrote on socket: Server: Windows XP-x86-5.1 UPnP/1.0, PMS
[Thread-129] DEBUG 16:42:38.234 Wrote on socket:
[Thread-129] DEBUG 16:42:38.234 Suspend Read: readCount=0 / writeCount=0
[Timer-6] DEBUG 16:42:38.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:39.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:40.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:41.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:42.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:43.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:44.312 Buffered Space: 0 bytes
[Timer-6] DEBUG 16:42:45.312 Buffered Space: 0 bytes
[Thread-129] DEBUG 16:42:45.734 Resume Read: readCount=0 / writeCount=0
[Thread-129] DEBUG 16:42:45.734 Suspend Read: readCount=32768 / writeCount=0
[Timer-6] DEBUG 16:42:46.312 Buffered Space: -32768 bytes
[Timer-6] DEBUG 16:42:47.312 Buffered Space: -32768 bytes
[Timer-6] DEBUG 16:42:48.312 Buffered Space: -32768 bytes
[Thread-19] DEBUG 16:42:48.828 Searching network interface for 192.168.1.101
[Thread-19] DEBUG 16:42:48.843 Searching network interface for 192.168.1.101
[Timer-6] DEBUG 16:42:49.312 Buffered Space: -32768 bytes
[Timer-6] DEBUG 16:42:50.312 Buffered Space: -32768 bytes
[Timer-6] DEBUG 16:42:51.312 Buffered Space: -32768 bytes
[Timer-6] DEBUG 16:42:52.312 Buffered Space: -32768 bytes
[Thread-129] DEBUG 16:42:53.234 Resume Read: readCount=32768 / writeCount=0
[Thread-129] DEBUG 16:42:53.234 Suspend Read: readCount=65536 / writeCount=0
[Timer-6] DEBUG 16:42:53.312 Buffered Space: -65536 bytes
[Timer-6] DEBUG 16:42:54.312 Buffered Space: -65536 bytes
[Timer-6] DEBUG 16:42:55.312 Buffered Space: -65536 bytes
[Timer-6] DEBUG 16:42:56.312 Buffered Space: -65536 bytes
[Timer-6] DEBUG 16:42:57.312 Buffered Space: -65536 bytes
[Timer-6] DEBUG 16:42:58.312 Buffered Space: -65536 bytes
[Timer-6] DEBUG 16:42:59.312 Buffered Space: -65536 bytes
[Timer-6] DEBUG 16:43:00.312 Buffered Space: -65536 bytes
[Thread-129] DEBUG 16:43:00.734 Resume Read: readCount=65536 / writeCount=0
[Thread-129] DEBUG 16:43:00.734 Suspend Read: readCount=98304 / writeCount=0
[Timer-6] DEBUG 16:43:01.312 Buffered Space: -98304 bytes
[Timer-6] DEBUG 16:43:02.312 Buffered Space: -98304 bytes
[Timer-6] DEBUG 16:43:03.312 Buffered Space: -98304 bytes
[Timer-6] DEBUG 16:43:04.312 Buffered Space: -98304 bytes
[Timer-6] DEBUG 16:43:05.312 Buffered Space: -98304 bytes
[Timer-6] DEBUG 16:43:06.312 Buffered Space: -98304 bytes
[Timer-6] DEBUG 16:43:07.312 Buffered Space: -98304 bytes
[Thread-129] DEBUG 16:43:08.234 Resume Read: readCount=98304 / writeCount=0
[Thread-129] DEBUG 16:43:08.234 Suspend Read: readCount=131072 / writeCount=0
[Timer-6] DEBUG 16:43:08.312 Buffered Space: -131072 bytes
[Timer-6] DEBUG 16:43:09.312 Buffered Space: -131072 bytes
[Timer-6] DEBUG 16:43:10.312 Buffered Space: -131072 bytes
[Timer-6] DEBUG 16:43:11.312 Buffered Space: -131072 bytes
[Timer-6] DEBUG 16:43:12.312 Buffered Space: -131072 bytes
[Timer-6] DEBUG 16:43:13.312 Buffered Space: -131072 bytes
[Timer-6] DEBUG 16:43:14.312 Buffered Space: -131072 bytes
[Timer-6] DEBUG 16:43:15.312 Buffered Space: -131072 bytes
[Thread-129] DEBUG 16:43:15.734 Resume Read: readCount=131072 / writeCount=0
[Thread-129] DEBUG 16:43:15.734 Suspend Read: readCount=163840 / writeCount=0
[Timer-6] DEBUG 16:43:16.312 Buffered Space: -163840 bytes
[Timer-6] DEBUG 16:43:17.312 Buffered Space: -163840 bytes
[Timer-6] DEBUG 16:43:18.312 Buffered Space: -163840 bytes
[Timer-6] DEBUG 16:43:19.312 Buffered Space: -163840 bytes
[Timer-6] DEBUG 16:43:20.312 Buffered Space: -163840 bytes
[Timer-6] DEBUG 16:43:21.312 Buffered Space: -163840 bytes
[Timer-6] DEBUG 16:43:22.312 Buffered Space: -163840 bytes
[Thread-129] DEBUG 16:43:23.234 Resume Read: readCount=163840 / writeCount=0
[Thread-129] DEBUG 16:43:23.234 Suspend Read: readCount=196608 / writeCount=0
[Timer-6] DEBUG 16:43:23.312 Buffered Space: -196608 bytes
[Timer-6] DEBUG 16:43:24.312 Buffered Space: -196608 bytes
[Timer-6] DEBUG 16:43:25.312 Buffered Space: -196608 bytes
[Timer-6] DEBUG 16:43:26.312 Buffered Space: -196608 bytes
[Timer-6] DEBUG 16:43:27.312 Buffered Space: -196608 bytes
[Timer-6] DEBUG 16:43:28.312 Buffered Space: -196608 bytes
[Timer-6] DEBUG 16:43:29.312 Buffered Space: -196608 bytes
[Timer-6] DEBUG 16:43:30.312 Buffered Space: -196608 bytes
[Thread-129] DEBUG 16:43:30.734 Resume Read: readCount=196608 / writeCount=0
[Thread-129] DEBUG 16:43:30.734 Suspend Read: readCount=229376 / writeCount=0
[Timer-6] DEBUG 16:43:31.312 Buffered Space: -229376 bytes
[Timer-6] DEBUG 16:43:32.312 Buffered Space: -229376 bytes
[Timer-6] DEBUG 16:43:33.312 Buffered Space: 1034240 bytes
[Thread-130] DEBUG 16:43:33.484 Input #0, avs, from 'C:\DOCUME~1\Amarpaul\LOCALS~1\Temp\javaps3media\pms-avs-name of video.avi.avs':
[Thread-130] DEBUG 16:43:33.484 Duration: 01:45:32.82, start: 0.000000, bitrate: 0 kb/s
[Thread-130] DEBUG 16:43:33.484 Stream #0.0: Video: rawvideo, yuv420p, 704x290, 58739 kb/s, 23.98 tb(r)
[Thread-130] DEBUG 16:43:33.484 Output #0, vob, to 'pipe:':
[Thread-130] DEBUG 16:43:33.484 Stream #0.0: Video: mpeg2video, yuv420p, 704x290, q=2-31, 200 kb/s, 23.98 tb(c)
[Thread-130] DEBUG 16:43:33.484 Stream mapping:
[Thread-130] DEBUG 16:43:33.484 Stream #0.0 -> #0.0
[Thread-130] DEBUG 16:43:33.484 Press [q] to stop encoding
[Thread-130] DEBUG 16:43:33.484 [vob @ 0187AFE0]buffer underflow i=0 bufi=1996 size=3296
[Thread-130] DEBUG 16:43:33.484 [vob @ 0187AFE0]buffer underflow i=0 bufi=714 size=3305
[Thread-130] DEBUG 16:43:33.484 [vob @ 0187AFE0]buffer underflow i=0 bufi=2738 size=3305
[Thread-129] DEBUG 16:43:33.734 Resume Read: readCount=229376 / writeCount=4210688
[Timer-6] DEBUG 16:43:34.312 Buffered Space: 8138752 bytes
[Thread-129] DEBUG 16:43:34.640 Sending stream with premature end : 1146880 bytes of get/0$0$2$0$3$3$1$0$1/name of video.avi. Reason: An established connection was aborted by the software in your host machine
[Thread-129] DEBUG 16:43:34.640 Ready to Stop: true
[Thread-129] DEBUG 16:43:34.640 Sending stream: 1146880 bytes of get/0$0$2$0$3$3$1$0$1/name of video.avi
[Thread-129] DEBUG 16:43:34.640 Close Connection
[Timer-6] DEBUG 16:43:35.312 Buffered Space: 15249408 bytes
[Thread-135] INFO 16:43:35.343 Stopping process: win32/ffmpeg.exe
[Thread-134] INFO 16:43:35.343 Stopping process: win32/ffmpeg.exe
[Thread-134] INFO 16:43:35.343 Destroying buffer
[Thread-135] INFO 16:43:35.375 Destroying buffer
[Thread-134] INFO 16:43:35.578 Destroying buffer
[win32/ffmpeg.exe] DEBUG 16:43:35.578 EOF
[Thread-135] INFO 16:43:35.671 Destroying buffer
[Thread-19] DEBUG 16:43:48.875 Searching network interface for 192.168.1.101
[Thread-19] DEBUG 16:43:48.875 Searching network interface for 192.168.1.101

[shagrath]

"Stream #0.0: Video: mpeg2video, yuv420p, 704x290"

means the avisynth script is in error (it's the common size of the Avisynth message video). for trouble shooting:
1- relaunch it
2- before stopping, go check the file C:\DOCUME~1\Amarpaul\LOCALS~1\Temp\javaps3media\pms-avs-name of video.avi.avs and launch it on your computer to actually see the error

I would suspect the vsfilter.dll if you have subtitles

[blackstar]

I tried what you suggested, and the video doesnt play in the temporary folder and then FFDshow 'V' (red icon) shows in task bar, i highlight over it and its gone. I reinstalled ps3 media server, and upon looking at the transcoder tab, Avisynth/ffmpeg and Avisynth/Mencoder were disabled. There was no error message.

I open ed the file on Mencoder and it played fine. I also removed the subtitle files on the folder where the video is playing, and still didn't help.

I noticed under FFDshow video decoder settings that Avisynth was not checked. I checked it and video still didn't play.

[shagrath]

well, create an avisynth script yourself :

DirectShowSource("yourvideo.avi", convertfps=true)

if this does not play, then your avisynth installation is broken

[blackstar]

Tried AviSynth script and no go.

What possibilities could happen when my avisynth installation is broken? I reinstalled it many times. Anyway to fix the issue?

BTW, I was able to get the video to run on the PC in the temporary javaps3server folder after the video stopped responding on the ps3.

[rankafan]

Tried AviSynth script and no go.

What possibilities could happen when my avisynth installation is broken? I reinstalled it many times. Anyway to fix the issue?

A broken AviSynth installation seems a rare, if not impossible scenario, really. And if you want to test an AVS script, be sure to associate it with something, of course, like Media Player Classic (or whatever floats your boat).

Also, define "no-go". What is not working? And what error messages do you get? If your AviSynth script really is a 'no-go', try logging:

DirectShowSource("yourvideo.avi", logfile="blah.log")

While DirectShowSource may noy be broken (read: AviSynth), certainly DirectShow itself, Microsoft's underlying multimedia framework and API, could be hosed. If that's the case, you're pretty much frakked. If you're on XP, you could try and reinstall Windows Media Player, in that case.