Broken multipart data

Question

Broken multipart data

Closed this issue a year ago · 28 comments

The problem manifested as an ArgumentError "invalid byte sequence in UTF-8" when trying to upload a PDF via Tomcat and jruby-rack to a simple application. Thanks to the simple reproduction by @jlahtinen I was able to narrow this down to a jruby-rack bug.

The code in jruby-rack has not been updated since JRuby 1.7, and as a result it was using some unsafe methods for concatenating bytes onto an existing string. Specifically, it called an old form of RubyString#cat that did not consider encoding or code range, and when it appended encoded or binary data onto an existing buffer it could break that buffer for any character operations.

Fix coming.

Answer 1 · 2024-05-23T03:37:50.000Z

@jlahtinen The fix is in, but I have additional work to get this building again. Bear with me! We'll have a new release of this out soon (almost a decade after the previous release) and no doubt there will be some complications. Work with me and we'll get it sorted out!

Answer 2 · 2024-05-23T05:06:41.000Z

@headius Thank you. I appreciate the progress being made and I understand that this takes as long as it takes :).

Answer 3 · 2024-05-23T17:07:02.000Z

I'm on the cusp of releasing this thing and all that stands in my way is getting authentication for pushing the maven artifact 🙄

Answer 4 · 2024-05-24T20:00:20.000Z

@jlahtinen Ok it's all released! jruby-rack 1.2.0 is released as a gem and maven artifact. Let's see if it works for you and shake out any remaining issues!

Answer 5 · 2024-05-29T05:43:33.000Z

Currently our app throws exception in tomcat when started

2024-05-29T05:15:41.244Z SEVERE org.apache.catalina.core.ApplicationContext log: initialization failed^_
org.jruby.rack.RackInitializationException: load error: /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/config/environment -- java.lang.NullPointerException: null
        from org/jruby/RubyKernel.java:1184:in `require'
        from uri:classloader:/jruby/rack/rails/environment3.rb:25:in `load_environment'
        from uri:classloader:/jruby/rack/rails_booter.rb:83:in `load_environment'
        from <script>:1:in `<main>'

        at org.jruby.rack.RackInitializationException.wrap(RackInitializationException.java:30)
        at org.jruby.rack.RackApplicationFactoryDecorator.init(RackApplicationFactoryDecorator.java:107)
        at org.jruby.rack.RackServletContextListener.contextInitialized(RackServletContextListener.java:50)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4462)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:4914)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:683)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:658)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:662)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1023)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1910)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118)
        at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:824)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:474)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1617)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:318)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:114)
        at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:402)
        at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:345)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:893)
        at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:795)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1332)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1322)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:866)
        at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:249)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
        at org.apache.catalina.core.StandardService.startInternal(StandardService.java:433)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
        at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:922)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:772)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:347)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:478)
Caused by: org.jruby.exceptions.LoadError: (LoadError) load error: /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/config/environment -- java.lang.NullPointerException: null
        at org.jruby.RubyKernel.require(org/jruby/RubyKernel.java:1184)
        at RUBY.load_environment(uri:classloader:/jruby/rack/rails/environment3.rb:25)
        at RUBY.load_environment(uri:classloader:/jruby/rack/rails_booter.rb:83)
        at RUBY.<main>(<script>:1)
Caused by: java.lang.NullPointerException
        at org.jruby.rack.ext.Logger.isEnabledFor(Logger.java:185)
        at org.jruby.rack.ext.Logger.add(Logger.java:353)
        at org.jruby.rack.ext.Logger.error(Logger.java:296)
        at org.jruby.rack.ext.Logger$INVOKER$i$1$0$error.call(Logger$INVOKER$i$1$0$error.gen)
        at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:423)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:466)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:244)
        loads of lines after this

I am not sure what is happening yet. I try to figure this out. If you @headius have any tips it would be much appreciated.

Answer 6 · 2024-05-29T05:45:13.000Z

I would like to add that this is happening after initialization fails. Maybe something to investigate or not ...

2024-05-29T05:26:02.435Z INFO org.apache.catalina.core.ApplicationContext log: due a previous initialization failure application instance can not be returned^_
2024-05-29T05:26:02.436Z INFO org.apache.catalina.core.ApplicationContext log: resetting rack response due exception^_
2024-05-29T05:26:02.438Z SEVERE org.apache.catalina.core.ApplicationContext log: error app failed to handle exception: org.jruby.rack.RackInitializationException: load error: /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/config/environment -- java.lang.NullPointerException: null
        from org/jruby/RubyKernel.java:1184:in `require'
        from uri:classloader:/jruby/rack/rails/environment3.rb:25:in `load_environment'
        from uri:classloader:/jruby/rack/rails_booter.rb:83:in `load_environment'
        from <script>:1:in `<main>'
^_
org.jruby.exceptions.NoMethodError: (NoMethodError) undefined method `bytesize' for Rack::Utils:Module
        at RUBY.call(uri:classloader:/jruby/rack/error_app/show_status.rb:30)
        at org.jruby.rack.ext.Servlet.call(org/jruby/rack/ext/Servlet.java:83)

Answer 7 · 2024-05-29T09:12:32.000Z

I removed all initializers and got a new problem. I debugged and found that missing constant is KirApplicationAware. I see that it is in directory app/models/concerns.

It is a module

module Concerns::KirApplicationAware
  extend ActiveSupport::Concern

org.jruby.rack.RackInitializationException: No such file to load -- java.lang.NullPointerException: null.rb
        from org/jruby/RubyKernel.java:1184:in `require'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:333:in `block in require'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:300:in `load_dependency'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:333:in `require'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:425:in `block in require_or_lo
ad'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:39:in `block in load_interlock
'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies/interlock.rb:14:in `block in load
ing'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/concurrency/share_lock.rb:151:in `exclusive'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies/interlock.rb:13:in `loading'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:39:in `load_interlock'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:403:in `require_or_load'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:559:in `load_missing_constant'
        from /usr/share/tomcat9/sikke_apps/ROOT/WEB-INF/gems/gems/activesupport-6.1.7.7/lib/active_support/dependencies.rb:214:in `const_missing
        ...
        ...
        Caused by: java.lang.NullPointerException
        at org.jruby.rack.ext.Logger.isEnabledFor(Logger.java:185)
        at org.jruby.rack.ext.Logger.add(Logger.java:353)
        at org.jruby.rack.ext.Logger.error(Logger.java:296)
        at org.jruby.rack.ext.Logger$INVOKER$i$1$0$error.call(Logger$INVOKER$i$1$0$error.gen)
        at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:423)

Another app that does not include custom initializes or concerns fails to same as this #247 (comment)

Answer 8 · 2024-05-29T12:16:34.000Z

In module Concerns::KirApplicationAware I had code like

included do
  name.constantize.new # name here could bee SomeClass
end

So it tried to load the class(SomeClass) that initially started loading Concerns::KirApplicationAware and failed.

example SomeClass code:

class SomeClass
  inlucde Concerns::KirApplicationAware
end

By changing name.constantize.new to self.class.new fixed #247 (comment)

Answer 9 · 2024-05-29T14:35:54.000Z

I found the initializer that fails. It fails to .each in Delayed::Job.all.each

Answer 10 · 2024-05-29T16:33:03.000Z

I'll help look into this later today!

Answer 11 · 2024-05-29T18:23:44.000Z

loads of lines after this

Can you provide those lines? The logger field is null, which would mean it was passed in as null during initialize of the Logger instance.

I found the initializer that fails

Do you have a backtrace for that?

I'm active on JRuby's Matrix channel now if you want to work on this, otherwise I can be active later or tomorrow if you give me a time.

Answer 12 · 2024-06-05T15:18:07.000Z

@headius trying with newly released jruby-rack 1.2.0:

java.lang.NoSuchMethodError: org.jruby.RubyString.catWithCodeRange(Lorg/jruby/util/ByteList;I)I
	org.jruby.rack.ext.Input.read(Input.java:147)
	org.jruby.rack.ext.Input$INVOKER$i$0$2$read.call(Input$INVOKER$i$0$2$read.gen)
	org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:828)
	org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:226)
	org.jruby.runtime.callsite.RefinedCachingCallSite.call(RefinedCachingCallSite.java:107)
	org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:325)
	org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)
	org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:92)
	org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:238)
	org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:225)
	org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:226)
	org.jruby.runtime.callsite.RefinedCachingCallSite.call(RefinedCachingCallSite.java:107)
	org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:325)
	org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)
	org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:128)
	org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:115)
	org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:329)
	org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:87)
	org.jruby.ir.instructions.CallBase.interpret(CallBase.java:549)
	org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:361)
	org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)
	org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:92)
	org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:238)
	org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:225)
	org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:226)
	org.jruby.runtime.callsite.RefinedCachingCallSite.call(RefinedCachingCallSite.java:107)
	org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:325)
	org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)
	org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:80)
	org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:164)
	org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:151)
	org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:210)
	org.jruby.runtime.callsite.RefinedCachingCallSite.call(RefinedCachingCallSite.java:59)
	C_3a_.Program_20_Files_20_28_x86_29_.acmeprotect.acme_20_Files.Access_20_Server.Web_20_Application.WEB_minus_INF.gems.gems.rack_minus_2_dot_2_dot_9.lib.rack.request.invokeOther9:parse_multipart(C:/Program Files (x86)/acmeprotect/acme Files/Access Server/Web Application/WEB-INF/gems/gems/rack-2.2.9/lib/rack/request.rb:447)
	C_3a_.Program_20_Files_20_28_x86_29_.acmeprotect.acme_20_Files.Access_20_Server.Web_20_Application.WEB_minus_INF.gems.gems.rack_minus_2_dot_2_dot_9.lib.rack.request.RUBY$method$POST$0(C:/Program Files (x86)/acmeprotect/acme Files/Access Server/Web Application/WEB-INF/gems/gems/rack-2.2.9/lib/rack/request.rb:447)

is that because we're on JRuby 9.3?

Answer 13 · 2024-06-05T17:32:23.000Z

@dolzenko Yes that's likely the issue. Those methods were added in 9.4 to get rid of some "19"-suffixed names that don't make sense anymore.

I could be convinced to support 9.3 in jruby-rack 1.2.x perhaps. Alternatively there may be a good argument for doing another 1.1.x release with just this fix. Did you need the fix from this issue?

Answer 14 · 2024-06-06T06:39:04.000Z

@headius thanks a lot, fix would be great since we're stuck with 9.3 for the rest of the year for sure. Another 1.1.x release sounds simpler? If you can do that it would be awesome

Answer 15 · 2024-06-06T18:30:43.000Z

@dolzenko I've pushed #255 which brings this fix to the 1.1.x line and will work with @kares to get a 1.1.23 released. I'll also merge this same change to master for 1.2.1, so you could try building from there if you are adventurous!

Answer 16 · 2024-06-08T13:49:19.000Z

@jlahtinen Ok it's all released! jruby-rack 1.2.0 is released as a gem and maven artifact. Let's see if it works for you and shake out any remaining issues!

Hiya @headius Did you mis-speak here ? This is not actually released as a Maven artifact to Maven Central right? https://central.sonatype.com/artifact/org.jruby.rack/jruby-rack Perhaps you are still stuck on Maven Central.

Answer 17 · 2024-06-08T15:40:45.000Z

@chadlwilson I am confused, I'm sure I went through the release process. I will look into this over the weekend.

Answer 18 · 2024-06-10T16:45:52.000Z

Ok I have no explanation. I recall going through the Maven release process, but it's not out there. I'll spin a 1.2.1 that has the Maven artifact out there as well.

Answer 19 · 2024-06-10T16:56:55.000Z

Looks like there were some validations for maven central that failed to pass for the release of 1.2.1. I'll work on getting those fixed.

Answer 20 · 2024-06-10T17:23:32.000Z

Sure, no worries :-) Thanks @headius !

Answer 21 · 2024-06-10T18:07:44.000Z

FWIW, whatever this release is, it will also have changes to support 9.3 for that one method call.

Answer 22 · 2024-06-10T21:29:00.000Z

Success! I have released 1.2.2 to Maven Central and Rubygems.org. I'm tidying up the issues now but it includes fixes to work on 9.3 and javadoc updates (that prevented 1.2.0 and 1.2.1 from pushing to Maven Central successfully).

Answer 23 · 2024-08-22T09:04:49.000Z

@headius Hello, we've been still experiencing the issue with jruby 9.3 once we install jruby-rack 1.2.2. Could you please clarify which version contains the fix for ruby 9.3 definitely? I see in correspondence you wanted to have the fix in 1.1.23, but it's missed among versions in rubygems.org, may be we should use a branch as source?

Answer 24 · 2024-08-22T09:32:10.000Z

1.1.23 not tagged or released. And 1.1 fixes over years not yet forward ported to 1.2 so "buyer beware".

Answer 25 · 2024-08-23T04:49:45.000Z

@DZverev what exception you are facing? I was able to fix multipart data problems with new jruby-rack but faced some new problems along the way. Maybe I can help you if I understand better what you are facing.

Could master...jlahtinen:jruby-rack:kvp5 help you?

Answer 26 · 2024-08-23T11:16:40.000Z

@jlahtinen it seems this fix helped us, thanks. @headius Is there chance to release the fix and continue maintain 9.3 version?

Answer 27 · 2024-08-29T04:05:05.000Z

Hey there! Sorry for the delays. I will look at getting the additional fix(es) rolled into a new 1.2.x release.

@jlahtinen Could you help me one more time with a list of the fixes we need to get released?

Answer 28 · 2024-08-29T04:44:56.000Z

@headius I think the only thing left is to handle java.lang.LinkageError https://gist.github.com/jlahtinen/11b51e1d5eee4069610789c085723b5b

I "fixed" it with master...jlahtinen:jruby-rack:kvp5 but I think that might break some other use cases.