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
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"