view · edit · sidebar · attach · print · history

< Niklaus.20161025-steinwies-rack-post | Index | Niklaus.20161019-steinwies-rack-post >>

20161024-steinwies-rack-post

Summary

  • port sbsm/steinwies.ch to use the rack webserver. Fix handling POST requests
  • Keep in Mind

Commits

Index

Why do we have a duplicate job on thinpower?

Looking at I find /var/www/oddb.org/log/oddb/debug/2016/10.log

2016-10-23 07:39:54 CESTlog notify Fach- und Patienteninfo Updates (swissmedicinfo.ch): sent mail
2016-10-23 07:39:54 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:494:in `get_latest_file':  cmd @latest_packungen = '/var/www/oddb.org/data/xls/Packungen-latest.xlsx'
2016-10-23 07:39:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:531:in `get_latest_file':  skip writing /var/www/oddb.org/data/xls/Packungen-2016.10.23.xlsx as /var/www/oddb.org/data/xls/Packungen-latest.xlsx is 3044450 bytes. Returning latest_name /var/www/oddb.org/data/xls/Packungen-latest.xlsx
2016-10-23 07:39:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:186:in `update': opts {} @update_comps  update target nilLatest /var/www/oddb.org/data/xls/Packungen-latest.xlsx 3044450 bytes
2016-10-23 07:39:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:309:in `update': file2open  nothing to do for opts {}
2016-10-23 07:39:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:312:in `update':  done. 0 export_registrations @update_comps was  with no change information
2016-10-23 07:39:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:313:in `update':  done0. $swissmedic_do_tracing is . Having 1 threads
2016-10-23 07:39:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:315:in `update':  done1. $swissmedic_do_tracing is false. Having 1 threads
2016-10-23 07:39:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 11603 MB of memory. Limit is 16384
2016-10-23 07:40:57 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 11603 MB of memory. Limit is 16384
2016-10-23 07:42:00 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 11603 MB of memory. Limit is 16384
<...>
2016-10-24 04:46:16 CEST safe_export price_history.csv completed
2016-10-24 04:46:16 CEST restart_export_server. Called from /var/www/oddb.org/src/util/exporter.rb:80
2016-10-24 04:47:03 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 12819 MB of memory. Limit is 16384
2016-10-24 04:47:16 CEST restart_export_server. Done sleeping 60 seconds
2016-10-24 04:48:05 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 12819 MB of memory. Limit is 16384
2016-10-24 04:49:07 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 12819 MB of memory. Limit is 16384
2016-10-24 04:50:09 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 12819 MB of memory. Limit is 16384
<..>
2016-10-24 07:00:34 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 12819 MB of memory. Limit is 16384
2016-10-24 07:01:36 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:163:in `trace_memory_useage': Using 12819 MB of memory. Limit is 16384
2016-10-24 07:01:37 CESTlog notify Duplicate Job: import_daily: start outgoing process ["log"]. Must attach 0 files and 0 parts.
2016-10-24 07:01:37 CESTUtil.send_mail list_and_recipients ["log"]

Had to look back much further. Looks like the swissmedic did not finish correctly on October 23 around 07:40.

The interesting line is 2016-10-23 07:39:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:313:in `update': done0. $swissmedic_do_tracing is . Having 1 threads.

Here we see that the variable $swissmedic_do_tracing is nil. This is the first occurrence of $swissmedic_do_tracing is . in the log file. Therefore pushing the creating of $swissmedic_do_tracing to the beginning of update method.

Pushed commit Fix race condition which lead to duplicate jobs

port sbsm/steinwies.ch to use the rack webserver. Fix handling POST requests

Why does a POST request not return the correct content? Updating sbsm and steinwies.ch readme, version, etc to prepare a report, on what does work and what does not.

Pushed the doc/cleanup commits

Wrote E-Mail to yasuhiro.

Trying to make steinwies.ngiger.ch to work again. Installing mod_ruby.so from Ruby186 and verifying that /etc/apache2/modules.d/21_mod_ruby.conf contains the same stuff as on fastpower. Checkout under /var/www/steinwies.ch the same cmmit 323cc79e00ba144233bb34514182007721f98317 as on fastpower. Now steinwies.ngiger.ch works. As I want to want to know how sbsm works. I am trying to add some pry statement. Adding gem 'pry-byebug' to the Gemfile and running sudo -u apache /usr/local/bin/bundle install. Now I am able to add a sudo -u apache /usr/local/bin/bundle install into lib/sbsm/session.rb at the beginning of the process methods. Now going only into pry unless request.request_method.eql?('GET') and I can ignore all GET request. Adding some info from the pry

@request_path
=> "/en/page"
 @validator
=> #<Steinwies::Validator:0x000000036af498
 @boolean=[],
 @dates=[],
 @enums={},
 @errors={},
 @events=[:back, :home, :person, :schwerpunkte, :dissertation, :lageplan, :kontakt, :links, :confirm, :sent, :sendmail],
 @files=[],
 @html=[],
 @numeric=[],
 @patterns={},
 @strings=[:anrede, :name, :vorname, :firma, :adresse, :ort, :telefon, :bestell_diss, :bestell_pedi, :text],
 @uris=[]>
 request.params
=> {"confirm"=>["Weiter"],
 "name"=>[""],
 "zone"=>"page",
 "language"=>"en",
 "text"=>["Test"],
 "bestell_diss"=>[""],
 "firma"=>[""],
 "event"=>["confirm"],
 "telefon"=>[""],
 "anrede"=>[""],
 "default_flavor"=>nil,
 "bestell_pedi"=>[""],
 "ort"=>[""],
 "flavor"=>[""],
 "adresse"=>[""],
 "vorname"=>[""],
 "state_id"=>["30410800"],
 "email"=>["test@test.com"]}
request.params['state_id']
=> ["30410800"]
 @unsafe_input
=> [["confirm", "[\"Weiter\"]"],
 ["name", "[\"\"]"],
 ["zone", "page"],
 ["language", "en"],
 ["text", "[\"Test\"]"],
 ["bestell_diss", "[\"\"]"],
 ["firma", "[\"\"]"],
 ["event", "[\"confirm\"]"],
 ["telefon", "[\"\"]"],
 ["anrede", "[\"\"]"],
 ["default_flavor", ""],
 ["bestell_pedi", "[\"\"]"],
 ["ort", "[\"\"]"],
 ["flavor", "[\"\"]"],
 ["adresse", "[\"\"]"],
 ["vorname", "[\"\"]"],
 ["state_id", "[\"30410800\"]"],
 ["email", "[\"test@test.com\"]"]]
 pry(#<Steinwies::Session>)> @valid_input
=> {:confirm=>nil,
 :name=>"",
 :zone=>nil,
 :language=>"en",
 :text=>"Test",
 :bestell_diss=>"",
 :firma=>"",
 :event=>:confirm,
 :telefon=>"",
 :anrede=>"",
 :default_flavor=>nil,
 :bestell_pedi=>"",
 :ort=>"",
 :flavor=>"",
 :adresse=>"",
 :vorname=>"",
 :state_id=>30410800,
 :email=>"test@test.com"}
request.cookies
=> #<DRb::DRbUnknown:0x007fb2752b2f30
 @buf=
  "\x04\b}\b\"\esbsm-persistent-cookieo:\x10CGI::Cookie\f:\f@domain0:\n@path\"\x06/:\f@secureF:\r@_dc_obj[\x06\"\x10language=en:\v@value@\t:\r@expires0:\n@name\"\esbsm-persistent-cookie\"\x15oddb-preferenceso;\x00\f;\x060;\a\"\x06/;\bF;\t[\x06\"\x10language=en;\n@\x0F;\v0;\f\"\x15oddb-preferences\"\x10_session_ido;\x00\f;\x060;\a\"\x06/;\bF;\t[\x06\"%01a29dd94812ae17a5d1c472e0adb7e7;\n@\x15;\v0;\f\"\x10_session_id[\x00",
 @name=nil>
@cookie_input
 @state = active_state.trigger(event())
[15] pry(#<Steinwies::Session>)> @state.class
=> Steinwies::ConfirmState
[16] pry(#<Steinwies::Session>)> event()
=> :confirm

I think I found the culprit. Here the trigger method returns Steinwies::ConfirmState where as I think, it returned Steinwies::HomeState with webrick/rack.

Now debugging the trigger method

[11] pry(#<Steinwies::Session>)> @valid_input[:state_id]
=> 16082360
[12] pry(#<Steinwies::Session>)> @valid_input['state_id']
=> nil

From: /var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/state.rb @ line 192 SBSM::State#trigger:

    183:                def trigger(event)
    184:       if(@redirected)
    185:         @redirected = false
    186:       else
    187:         @errors = {}
    188:         @infos = []
    189:         @warnings = []
    190:       end
    191:                        state = if(event && !event.to_s.empty? && self.respond_to?(event))
 => 192:                                _trigger(event)
    193:                        elsif(klass = @events[event])
    194:                                klass.new(@session, @model)
    195:                        end
    196:                        state ||= self.default
    197:                        if(state.respond_to?(:previous=))
    198:                                state.previous = self
    199:                        end
    200:                        state
    201:                end

[7] pry(#<Steinwies::KontaktState>)> step

From: /var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/state.rb @ line 203 SBSM::State#_trigger:

    202: def _trigger(event)
 => 203:   self.send(event)
    204: end

[7] pry(#<Steinwies::KontaktState>)> step

From: /var/www/steinwies.ch/src/state/kontakt.rb @ line 13 Steinwies::KontaktState#confirm:

    12: def confirm
 => 13:   mail = KontaktMail.new(@session)
    14:   if mail.ready?
    15:     ConfirmState.new(@session, mail)
    16:   else
    17:     mail.errors.push(:email)
    18:     @model = mail
    19:     self
    20:   end
    21: end
[9] pry(#<Steinwies::KontaktState>)> next

From: /var/www/steinwies.ch/src/state/kontakt.rb @ line 15 Steinwies::KontaktState#confirm:

    12: def confirm
    13:   mail = KontaktMail.new(@session)
    14:   if mail.ready?
 => 15:     ConfirmState.new(@session, mail)
    16:   else
    17:     mail.errors.push(:email)
    18:     @model = mail
    19:     self
    20:   end
    21: end

[9] pry(#<Steinwies::KontaktState>)> next

From: /var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/state.rb @ line 196 SBSM::State#trigger:

    183:                def trigger(event)
    184:       if(@redirected)
    185:         @redirected = false
    186:       else
    187:         @errors = {}
    188:         @infos = []
    189:         @warnings = []
    190:       end
    191:                        state = if(event && !event.to_s.empty? && self.respond_to?(event))
    192:                                _trigger(event)
    193:                        elsif(klass = @events[event])
    194:                                klass.new(@session, @model)
    195:                        end
 => 196:                        state ||= self.default
    197:                        if(state.respond_to?(:previous=))
    198:                                state.previous = self
    199:                        end
    200:                        state
    201:                end

Adding a simple debug line returns for visiting

Handling requrest GET state_id is  for /en/page/home/
Handling requrest GET state_id is  for /en/page/person/
Handling requrest GET state_id is  for /en/page/schwerpunkte/
Handling requrest GET state_id is  for /en/page/dissertation/
Handling requrest GET state_id is  for /en/page/lageplan/
Handling requrest GET state_id is  for /en/page/kontakt/
Handling requrest POST state_id is 20086380 for /en/page

Changed the servername in etc/config.yml of my lokal git workspace to localhost:8004. Now I am able to work in parallel with steinwies.ngiger.ch and localhost:8004, which is very handy for debugging.

Adding another puts gives for steinwies.ch

/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 357: Handling request GET state_id is  for /
sbsm/state.rb 193 Steinwies::HomeState: triggered event 
/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 357: Handling request GET state_id is  for /en/page/person/
sbsm/state.rb 193 Steinwies::HomeState: triggered event person
/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 357: Handling request GET state_id is  for /en/page/kontakt/
sbsm/state.rb 193 Steinwies::PersonState: triggered event kontakt
/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 357: Handling request POST state_id is 29451360 for /en/page

There is clearly a problem that the request_path returned by mod_ruby was not set correctly with my changes. But on the otherside mod_ruby used the trans_handler to modify it request_path. But when? In a session? Or a request? Will ponder again tomorrow.

Here is an additional trace, which shows the difference of the get of kontakt and dissertation

165: request_path is 
sbsm//var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 359: Handling request GET state_id is  for /
/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 538 active_state is  or #<Steinwies::HomeState:0x000000027c41b8>
sbsm/state.rb 193 Steinwies::HomeState: triggered event 
165: request_path is /
sbsm//var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 359: Handling request GET state_id is  for /
/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 538 active_state is  or #<Steinwies::HomeState:0x000000027c41b8>
sbsm/state.rb 193 Steinwies::HomeState: triggered event 
165: request_path is /
sbsm//var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 359: Handling request GET state_id is  for /en/page/dissertation/
/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 538 active_state is  or #<Steinwies::HomeState:0x000000027c41b8>
sbsm/state.rb 193 Steinwies::HomeState: triggered event dissertation
165: request_path is /en/page/dissertation/
sbsm//var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 359: Handling request GET state_id is  for /en/page/kontakt/
/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 538 active_state is  or #<Steinwies::DissertationState:0x00000002ad25f8>
sbsm/state.rb 193 Steinwies::DissertationState: triggered event kontakt
165: request_path is /en/page/kontakt/
sbsm//var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 359: Handling request POST state_id is 22135800 for /en/page
165: request_path is /en/page/kontakt/
sbsm//var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 359: Handling request POST state_id is  for /en/page

From: /var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb @ line 362 SBSM::Session#process:

    357:                                import_user_input(request)
    358:                                import_cookies(request)
    359:                               puts "sbsm/#{__FILE__} #{__LINE__}: Handling request #{request.request_method} state_id is #{@valid_input[:state_id]} for #{@request_path}"
    360: 
    361:                        require 'pry'; binding.pry unless request.request_method.eql?('GET')
 => 362:                                @state = active_state.trigger(event())
    363:         #FIXME: is there a better way to distinguish returning states?
    364:         #       ... we could simply refuse to init if event == :sort, but that
    365:         #       would not solve the problem cleanly, I think.
    366:         unless(@state.request_path)
    367:           @state.request_path = @request_path

[1] pry(#<Steinwies::Session>)> self.class
=> Steinwies::Session
[2] pry(#<Steinwies::Session>)> next
/var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb 538 active_state is  or #<Steinwies::KontaktState:0x00000003512680>
sbsm/state.rb 193 Steinwies::KontaktState: triggered event confirm
sbsm/state.rb 197 Steinwies::KontaktState: triggered confirm respond_to? true

From: /var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb @ line 366 SBSM::Session#process:

    361:                        require 'pry'; binding.pry unless request.request_method.eql?('GET')
    362:                                @state = active_state.trigger(event())
    363:         #FIXME: is there a better way to distinguish returning states?
    364:         #       ... we could simply refuse to init if event == :sort, but that
    365:         #       would not solve the problem cleanly, I think.
 => 366:         unless(@state.request_path)
    367:           @state.request_path = @request_path
    368:           @state.init
    369:         end
    370:                                unless @state.volatile?
    371:                                        @active_state = @state

[2] pry(#<Steinwies::Session>)> next

From: /var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb @ line 367 SBSM::Session#process:

    362:                                @state = active_state.trigger(event())
    363:         #FIXME: is there a better way to distinguish returning states?
    364:         #       ... we could simply refuse to init if event == :sort, but that
    365:         #       would not solve the problem cleanly, I think.
    366:         unless(@state.request_path)
 => 367:           @state.request_path = @request_path
    368:           @state.init
    369:         end
    370:                                unless @state.volatile?
    371:                                        @active_state = @state
    372:                                        @attended_states.store(@state.object_id, @state)

[2] pry(#<Steinwies::Session>)> next

From: /var/www/steinwies.ch/vendor/ruby/2.3.0/gems/sbsm-1.3.0/lib/sbsm/session.rb @ line 368 SBSM::Session#process:

    363:         #FIXME: is there a better way to distinguish returning states?
    364:         #       ... we could simply refuse to init if event == :sort, but that
    365:         #       would not solve the problem cleanly, I think.
    366:         unless(@state.request_path)
    367:           @state.request_path = @request_path
 => 368:           @state.init
    369:         end
    370:                                unless @state.volatile?
    371:                                        @active_state = @state
    372:                                        @attended_states.store(@state.object_id, @state)
    373:                                end

[2] pry(#<Steinwies::Session>)> @state.class
=> Steinwies::ConfirmState
[3] pry(#<Steinwies::Session>)> @request_path
=> "/en/page"
view · edit · sidebar · attach · print · history
Page last modified on October 24, 2016, at 06:20 PM