makemkvcon stalls prior to writing first output file

[salty]

Hi,

I've had an automated process running for quite some time that calls `makemkvcon` to rip iso, BDMV, and DVD... things.
It started failing one week ago.
I've looked at it today, finally, and see that it is able to scan and interpret the disk(s) just fine, but stalls just after it says it's starting to save the first output file:

```

Code: Select all

# makemkvcon --decrypt -r --progress=-same mkv file:BDMV/.. all .
MSG:1005,0,1,"MakeMKV v1.16.4 linux(x64-release) started","%1 started","MakeMKV v1.16.4 linux(x64-release)"
PRGT:5018,0,"Scanning CD-ROM devices"
PRGC:5018,0,"Scanning CD-ROM devices"
PRGV:0,0,65536
PRGV:0,0,65536
PRGV:65536,0,65536
PRGV:65536,65536,65536
DRV:0,0,999,0,"DVD-ROM PLDS DVD-ROM DS-8D3SH HD51","","/dev/sr0"
DRV:1,256,999,0,"","",""
DRV:2,256,999,0,"","",""
DRV:3,256,999,0,"","",""
DRV:4,256,999,0,"","",""
DRV:5,256,999,0,"","",""
DRV:6,256,999,0,"","",""
DRV:7,256,999,0,"","",""
DRV:8,256,999,0,"","",""
DRV:9,256,999,0,"","",""
DRV:10,256,999,0,"","",""
DRV:11,256,999,0,"","",""
DRV:12,256,999,0,"","",""
DRV:13,256,999,0,"","",""
DRV:14,256,999,0,"","",""
DRV:15,256,999,0,"","",""
PRGV:0,65536,65536
PRGV:0,0,65536
MSG:3006,131072,1,"Opening files on harddrive at file://BDMV/..","Opening files on harddrive at %1","file://BDMV/.."
PRGT:3404,0,"Opening Blu-ray disc"
PRGC:3400,0,"Processing AV clips"
PRGV:0,0,65536
PRGV:0,0,65536
PRGC:3401,0,"Processing movie playlists"
PRGC:3402,0,"Decrypting"
MSG:3305,0,0,"AACS directory not present, assuming unencrypted disc","AACS directory not present, assuming unencrypted disc"
PRGC:3406,0,"Processing BD+ code"
PRGC:3403,0,"Processing titles"
PRGV:3744,0,65536
PRGV:3744,313,65536
MSG:3307,0,2,"File 00001.mpls was added as title #0","File %1 was added as title #%2","00001.mpls","0"
PRGV:9362,313,65536
PRGV:9362,783,65536
MSG:3307,0,2,"File 00803.mpls was added as title #1","File %1 was added as title #%2","00803.mpls","1"
PRGV:13107,783,65536
PRGV:13107,1097,65536
MSG:3307,0,2,"File 00021.mpls was added as title #2","File %1 was added as title #%2","00021.mpls","2"
PRGV:18724,1097,65536
PRGV:18724,1567,65536
MSG:3307,0,2,"File 00801.mpls was added as title #3","File %1 was added as title #%2","00801.mpls","3"
PRGV:33704,1567,65536
PRGV:33704,2822,65536
MSG:3307,0,2,"File 00313.m2ts was added as title #4","File %1 was added as title #%2","00313.m2ts","4"
PRGV:35576,2822,65536
PRGV:35576,2978,65536
MSG:3307,16777216,2,"File 00307.m2ts was added as title #5","File %1 was added as title #%2","00307.m2ts","5"
MSG:3025,16777216,3,"Title #00230.m2ts has length of 0 seconds which is less than minimum title length of 120 seconds and was therefore skipped","Title #%1 has length of %2 seconds which is less than minimum title length of %3 seconds and was therefore skipped","00230.m2ts","0","120"
MSG:3025,0,3,"Title #00231.m2ts has length of 20 seconds which is less than minimum title length of 120 seconds and was therefore skipped","Title #%1 has length of %2 seconds which is less than minimum title length of %3 seconds and was therefore skipped","00231.m2ts","20","120"
PRGV:44938,2978,65536
PRGV:44938,3762,65536
MSG:3307,16777216,2,"File 00312.m2ts was added as title #6","File %1 was added as title #%2","00312.m2ts","6"
MSG:3025,16777216,3,"Title #00304.m2ts has length of 62 seconds which is less than minimum title length of 120 seconds and was therefore skipped","Title #%1 has length of %2 seconds which is less than minimum title length of %3 seconds and was therefore skipped","00304.m2ts","62","120"
MSG:3025,16777216,3,"Title #00295.m2ts has length of 62 seconds which is less than minimum title length of 120 seconds and was therefore skipped","Title #%1 has length of %2 seconds which is less than minimum title length of %3 seconds and was therefore skipped","00295.m2ts","62","120"
MSG:3025,16777216,3,"Title #00314.m2ts has length of 62 seconds which is less than minimum title length of 120 seconds and was therefore skipped","Title #%1 has length of %2 seconds which is less than minimum title length of %3 seconds and was therefore skipped","00314.m2ts","62","120"
MSG:3025,16777216,3,"Title #00310.m2ts has length of 69 seconds which is less than minimum title length of 120 seconds and was therefore skipped","Title #%1 has length of %2 seconds which is less than minimum title length of %3 seconds and was therefore skipped","00310.m2ts","69","120"
MSG:3025,0,3,"Title #00315.m2ts has length of 62 seconds which is less than minimum title length of 120 seconds and was therefore skipped","Title #%1 has length of %2 seconds which is less than minimum title length of %3 seconds and was therefore skipped","00315.m2ts","62","120"
PRGV:59918,3762,65536
PRGV:59918,5017,65536
MSG:3307,0,2,"File 00311.m2ts was added as title #7","File %1 was added as title #%2","00311.m2ts","7"
PRGV:61791,5017,65536
PRGV:61791,5173,65536
MSG:3307,16777216,2,"File 00309.m2ts was added as title #8","File %1 was added as title #%2","00309.m2ts","8"
MSG:3025,0,3,"Title #00305.m2ts has length of 81 seconds which is less than minimum title length of 120 seconds and was therefore skipped","Title #%1 has length of %2 seconds which is less than minimum title length of %3 seconds and was therefore skipped","00305.m2ts","81","120"
PRGV:65536,5173,65536
PRGV:65536,5487,65536
MSG:5011,0,0,"Operation successfully completed","Operation successfully completed"
PRGV:0,5487,65536
PRGV:0,0,65536
PRGT:5024,0,"Saving all titles to MKV files"
MSG:5014,131072,2,"Saving 9 titles into directory file://.","Saving %1 titles into directory %2","9","file://."
PRGC:5057,0,"Analyzing seamless segments"
PRGV:0,0,65536
PRGV:0,0,65536
PRGV:49152,0,65536
PRGC:5017,0,"Saving to MKV file"
PRGV:0,0,65536
PRGV:296,0,65536
PRGV:296,108,65536
```

and there it sits.

strace says:

Code: Select all

```
...
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
write(1, "PRGC:5017,0,\"Saving to MKV file\""..., 33) = 33
write(1, "PRGV:0,0,65536\n", 15)        = 15
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
write(1, "PRGV:296,0,65536\n", 17)      = 17
write(1, "PRGV:296,108,65536\n", 18)     = 19
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=50000000}, NULL) = 0
```

and those sleeps go forever.

The output file is created, but has no contents.

I've tried it with 1.16.4 (shown above) as well as 1.16.3, 1.16.2, 1.15.4, and 1.14.7.
They all fail in this way except for 1.14.7, which won't run at all (`Failed to initialize`).


I'm on Debian bullseye, but when this last worked, I was on buster.
It stopped working prior to that upgrade, pretty sure.

Anyone have a clue?

Thanks!

[mathias]

Hi salty,

I bet you're using the Debian packages I provide.

I hit this same issue today.... trying to convert a Blu-ray disc was stalling. Interestingly, trying to process a DVD resulted in a segfault:

Code: Select all

makemkvcon[117820]: segfault at 7fa56866aff8 ip 00007fa56fa247c9 sp 00007fa56866b000 error 6 in libmatroska.so.7.0.0[7fa56fa1a000+28000]
Code: 00 44 89 c0 c3 0f 1f 40 00 89 14 24 ff d0 8b 14 24 48 89 c7 e9 fc fe ff ff 0f 1f 84 00 00 00 00 00 41 57 41 56 41 55 41 54 55 <53> 48 83 ec 18 48 83 7f 38 00 0f 85 50 05 00 00 0f b7 47 7c 48 89

Running the process within gdb, when the segfault occurs, I get a huge stack, with over 104,000 repetitions of the call to libmatroska::KaxInternalBlock::UpdateSize(bool, bool):

Code: Select all

#104617 0x00007ffff5f88c36 in libmatroska::KaxInternalBlock::UpdateSize(bool, bool) () at /lib/x86_64-linux-gnu/libmatroska.so.7
#104618 0x00007ffff5f88126 in libmatroska::KaxInternalBlock::ValidateSize() const () at /lib/x86_64-linux-gnu/libmatroska.so.7
#104619 0x00007ffff5feaf67 in libebml::EbmlElement::RenderHead(libebml::IOCallback&, bool, bool, bool) () at /lib/x86_64-linux-gnu/libebml.so.5
#104620 0x00007ffff5feafda in libebml::EbmlElement::Render(libebml::IOCallback&, bool, bool, bool) () at /lib/x86_64-linux-gnu/libebml.so.5
#104621 0x00007ffff7f9b9b3 in MkvCreateFile () at /lib/x86_64-linux-gnu/libmakemkv.so.1
#104622 0x000000000076f491 in  ()
#104623 0x000000000076c5a1 in  ()
#104624 0x00000000007fc2e0 in  ()
#104625 0x000000000065aff1 in  ()
#104626 0x000000000065be44 in  ()
#104627 0x00007ffff7f69ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
#104628 0x00007ffff7e99def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

As the problem looked to be centered in (the Debian-supplied version of) libmatroska, I did a quick-and-dirty rebuild of my packages that compiled against the vendored versions of libmatroska and libbml. Voila -- conversion works again.

So, things work with the vendored versions of the libraries, but there's obviously some difference between how those versions and Debian's versions work. (Note though, that I didn't have to make any API changes to compile against the system version of those libraries -- the whole patch is at the bottom of this post.)

I'd really, really like to not depend on the bundled versions of these libraries. I understand they're there to help make the build process easier and require people to fetch fewer dependencies, but when a distro has API/ABI compatible versions, I'd prefer to use those instead.

It's getting pretty late for me, but tomorrow I'll spend some time looking at the code to see what changes are needed. If anyone has any pointers I'd appreciate them! It probably won't be until Friday that I push updated packages, either fixing the issue or reverting back to using the vendored libraries.

Mathias

Code: Select all

diff --git a/Makefile.in b/Makefile.in
index 224ef65..d7833dd 100644
--- a/Makefile.in
+++ b/Makefile.in
@@ -82,13 +82,13 @@ tmp/%.c.o: %.c
 
 out/libmakemkv.so.1.full: tmp/gen_buildinfo.h $(LIBABI_OBJ) $(LIBFFABI_OBJ)
 	mkdir -p out
-	$(GXX) $(CXXFLAGS) $(CFLAGS) $(LDFLAGS) $(NO_EC_DEF) -D_GNU_SOURCE -D_REENTRANT -shared -Wl,-z,defs -o$@ $(INCF)$(LIBEBML_INC) $(LIBEBML_DEF) \
-	$(INCF)$(LIBMATROSKA_INC) $(INCF)$(LIBMAKEMKV_INC) $(INCF)$(SSTRING_INC) $(INCF)$(MAKEMKVGUI_INC) $(INCF)$(LIBABI_INC) \
-	$(INCF)$(LIBFFABI_INC) $(LIBEBML_SRC) $(LIBMATROSKA_SRC) $(LIBMAKEMKV_SRC) $(SSTRING_SRC) $(LIBABI_SRC_LINUX) \
+	$(GXX) $(CXXFLAGS) $(CFLAGS) $(LDFLAGS) $(NO_EC_DEF) -D_GNU_SOURCE -D_REENTRANT -shared -Wl,-z,defs -o$@ -I/usr/include/ebml/ $(LIBEBML_DEF) \
+	-I/usr/include/matroska/ $(INCF)$(LIBMAKEMKV_INC) $(INCF)$(SSTRING_INC) $(INCF)$(MAKEMKVGUI_INC) $(INCF)$(LIBABI_INC) \
+	$(INCF)$(LIBFFABI_INC) $(LIBMAKEMKV_SRC) $(SSTRING_SRC) $(LIBABI_SRC_LINUX) \
 	$(LIBABI_OBJ) $(LIBFFABI_OBJ) \
 	-DHAVE_BUILDINFO_H -Itmp \
 	-fPIC -Xlinker -dy -Xlinker --version-script=libmakemkv/src/libmakemkv.vers \
-	-Xlinker -soname=libmakemkv.so.1 -lc -lstdc++ -lcrypto -lz -lexpat $(FFMPEG_LIBS) -lm -lrt
+	-Xlinker -soname=libmakemkv.so.1 -lc -lstdc++ -lcrypto -lz -lexpat $(FFMPEG_LIBS) -lm -lrt -lebml -lmatroska
 
 out/libmmbd.so.0.full:
 	mkdir -p out
diff --git a/libmakemkv/inc/lgpl/cassert b/libmakemkv/inc/lgpl/cassert
index 11ecd2a..8d17968 100644
--- a/libmakemkv/inc/lgpl/cassert
+++ b/libmakemkv/inc/lgpl/cassert
@@ -84,7 +84,7 @@ int MkvAssertHelper(const char* Message);
     (void)( (!!(_Expression_)) || (MkvAssertHelper("MKV_ASSERT: " #_Expression_ )) );
 
 #ifdef assert
-#error assert
+#undef assert
 #endif
 
 #define assert MKV_ASSERT
diff --git a/libmakemkv/src/ebmlwrite.cpp b/libmakemkv/src/ebmlwrite.cpp
index b5f2d85..93991e8 100644
--- a/libmakemkv/src/ebmlwrite.cpp
+++ b/libmakemkv/src/ebmlwrite.cpp
@@ -21,6 +21,7 @@
 #include <libmkv/libmkv.h>
 #include <libmkv/internal.h>
 #include <libmkv/ebmlwrite.h>
+#include <lgpl/cassert>
 #include <lgpl/stl.h>
 
 uint32 CEbmlWrite::read(void*Buffer,size_t Size)
diff --git a/libmakemkv/src/libmkv.cpp b/libmakemkv/src/libmkv.cpp
index c0b91c8..e91ba79 100644
--- a/libmakemkv/src/libmkv.cpp
+++ b/libmakemkv/src/libmkv.cpp
@@ -516,7 +516,7 @@ static void MkvCreateFileInternal(IOCallback &File,IMkvTrack *Input,IMkvTitleInf
     *static_cast<EbmlString *>(&MyDocType) = "matroska";
 
     EDocTypeVersion & MyDocTypeVer = GetChild<EDocTypeVersion>(FileHead);
-    *(static_cast<EbmlUInteger *>(&MyDocTypeVer)) = MATROSKA_VERSION;
+    *(static_cast<EbmlUInteger *>(&MyDocTypeVer)) = LIBMATROSKA_VERSION;
 
     EDocTypeReadVersion & MyDocTypeReadVer = GetChild<EDocTypeReadVersion>(FileHead);
     *(static_cast<EbmlUInteger *>(&MyDocTypeReadVer)) = 2;
diff --git a/libmakemkv/src/version.cpp b/libmakemkv/src/version.cpp
index c05ebdc..7f6183d 100644
--- a/libmakemkv/src/version.cpp
+++ b/libmakemkv/src/version.cpp
@@ -41,9 +41,9 @@ UTFstring GetLibraryVersionString()
     strcat(ver," ");
     strcat(ver,MAKEMKV_VERSION_NUMBER);
     strcat(ver," (");
-    strcat(ver,EbmlCodeVersion);
+    strcat(ver,EbmlCodeVersion.c_str());
     strcat(ver,"/");
-    strcat(ver,KaxCodeVersion);
+    strcat(ver,KaxCodeVersion.c_str());
     strcat(ver,")");
 #if defined(ARCH_NAME)
     strcat(ver," " ARCH_NAME);

[mathias]

Alright, I've pushed updated packages to my repo. For the time being, I've reverted back to using the bundled libraries rather than the Debian-provided ones. I wasn't able to easily figure out a fix, as the issue is down in those libraries and I'm not familiar enough with them to really understand why this issue is happening.

Mathias

[salty]

It had 'magically' started working again, after I did a general upgrade on the system, so I *think* that your shift to the bundled libs resolved things.

Thanks so much!

[BenTheTechGuy]

I noticed that with the 1.17.4 update some things were changed in the vendored libebml and libmatroska code, which gave me hope that using upstream libraries might work again. After testing it out, unfortunately the problem still exists, but with a different failing function. Here is the error:

Code: Select all

makemkvcon: ./src/EbmlElement.cpp:721: filepos_t libebml::EbmlElement::OverwriteData(libebml::IOCallback&, bool): Assertion `Result == DataSize' failed.

Here is part of the backtrace (full backtrace attached):

Code: Select all

#4  0x00007fd8a22f5395 in __assert_fail_base (fmt=0x7fd8a2469a70 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x7fd8a226c641 "Result == DataSize", file=file@entry=0x7fd8a226c5f5 "./src/EbmlElement.cpp", 
    line=line@entry=721, function=function@entry=0x7fd8a226ca58 "filepos_t libebml::EbmlElement::OverwriteData(libebml::IOCallback&, bool)")
    at ./assert/assert.c:92
        str = 0x7fd8900334e0 "3"
        total = 4096
#5  0x00007fd8a2303df2 in __GI___assert_fail (assertion=0x7fd8a226c641 "Result == DataSize", file=0x7fd8a226c5f5 "./src/EbmlElement.cpp", 
    line=721, function=0x7fd8a226ca58 "filepos_t libebml::EbmlElement::OverwriteData(libebml::IOCallback&, bool)") at ./assert/assert.c:101
No locals.
#6  0x00007fd8a2262260 in libebml::EbmlElement::OverwriteData (this=0x7fd89000c8f0, output=..., bKeepPosition=bKeepPosition@entry=true)
    at ./src/EbmlElement.cpp:721
        HeaderSize = <optimized out>
        DataSize = 44
        CurrentPosition = 5828
        Result = 47
        __PRETTY_FUNCTION__ = "filepos_t libebml::EbmlElement::OverwriteData(libebml::IOCallback&, bool)"

This seems to be the offending function:

Code: Select all

filepos_t EbmlElement::OverwriteData(IOCallback & output, bool bKeepPosition)
{
  if (ElementPosition == 0) {
    return 0; // the element has not been written
  }

  auto HeaderSize = EbmlId(*this).GetLength() + CodedSizeLength(Size, SizeLength, bSizeIsFinite);
#if !defined(NDEBUG)
  auto DataSize   = GetSize();
#endif

  auto CurrentPosition = output.getFilePointer();
  output.setFilePointer(GetElementPosition() + HeaderSize);
  auto Result = RenderData(output, true, bKeepPosition);
  output.setFilePointer(CurrentPosition);
  assert(Result == DataSize);
  return Result;
}

Looking at this function in both the upstream and vendored versions of libebml, the only difference is that DataSize = GetSize() is only being run in a debug environment if you're using the upstream version, while it's always run with the vendored version.

I have no experience debugging C(++) code past getting the backtrace, but I thought this information may be useful for those who do.