Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

puzzling ingestion of item "6bb30310-baa2-47f9-8ebc-5246370db71f" #311

Open
henryzhang87 opened this issue Apr 11, 2023 · 8 comments
Open
Assignees

Comments

@henryzhang87
Copy link
Collaborator

The first attempt to save that item started on April 9, 2023, then it throw some errors, as shown by the log file below:

I, [2023-04-09T11:18:41.635020 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: Retreiving data from Jupiter ...
D, [2023-04-09T11:18:41.903177 #19519] DEBUG -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: Creating directories ...
D, [2023-04-09T11:18:41.904121 #19519] DEBUG -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: Creating directories done
I, [2023-04-09T11:18:41.904555 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/metadata/object_metadata.n3 -- Downloading from aip/v1/items/6bb30310-baa2-47f9-8ebc-5246370db71f ...
I, [2023-04-09T11:18:44.055716 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/metadata/object_metadata.n3 -- Saved
I, [2023-04-09T11:18:44.056044 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/metadata/files_metadata/file_order.xml -- Downloading from aip/v1/items/6bb30310-baa2-47f9-8ebc-5246370db71f/filesets ...
I, [2023-04-09T11:18:44.104363 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/metadata/files_metadata/file_order.xml -- Saved
D, [2023-04-09T11:18:44.151808 #19519] DEBUG -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: Creating file set cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09 directories ...
D, [2023-04-09T11:18:44.152969 #19519] DEBUG -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: Creating file set cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09 directories done
I, [2023-04-09T11:18:44.153141 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/files/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/Insight 37_37.pdf -- Downloading from /era_assets/op/09/op09aeupu16locya2ir7ddnnos51 ...
I, [2023-04-09T11:18:44.174248 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/files/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/Insight 37_37.pdf -- Saved
I, [2023-04-09T11:18:44.174438 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/logs/files_logs/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/content_fixity_report.n3 -- Downloading from aip/v1/items/6bb30310-baa2-47f9-8ebc-5246370db71f/filesets/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/fixity ...
I, [2023-04-09T11:18:44.238937 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/logs/files_logs/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/content_fixity_report.n3 -- Saved
I, [2023-04-09T11:18:44.239141 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/metadata/files_metadata/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/file_set_metadata.n3 -- Downloading from aip/v1/items/6bb30310-baa2-47f9-8ebc-5246370db71f/filesets/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09 ...
I, [2023-04-09T11:18:45.490820 #19519]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/metadata/files_metadata/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/file_set_metadata.n3 -- Saved
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/container.rb:21: warning: URI.escape is obsolete
E, [2023-04-09T11:18:45.519429 #19519] ERROR -- : [Rollbar] Error calling the `transform` hook: undefined method `[]' for #<NoMethodError: undefined method `strip' for false:FalseClass>
I, [2023-04-09T11:18:45.519474 #19519]  INFO -- : [Rollbar] Scheduling item
I, [2023-04-09T11:18:45.519487 #19519]  INFO -- : [Rollbar] Sending item
I, [2023-04-09T11:18:45.519796 #19519]  INFO -- : [Rollbar] Sending json
I, [2023-04-09T11:18:45.691910 #19519]  INFO -- : [Rollbar] Success
I, [2023-04-09T11:18:45.692045 #19519]  INFO -- : [Rollbar] Details: https://rollbar.com/instance/uuid?uuid=2cf9d139-5f19-41a4-aaf9-eccc0fbac54b (only available if report was successful)
E, [2023-04-09T11:18:45.692196 #19519] ERROR -- : undefined method `strip' for false:FalseClass (NoMethodError)
/usr/lib64/ruby/2.7.0/net/http/header.rb:21:in `block in initialize_http_header'
/usr/lib64/ruby/2.7.0/net/http/header.rb:16:in `each'
/usr/lib64/ruby/2.7.0/net/http/header.rb:16:in `initialize_http_header'
/usr/lib64/ruby/2.7.0/net/http/generic_request.rb:46:in `initialize'

Many re-tries were attempted without success, till April 11, 2023, it finally got deposited into Swift

I, [2023-04-11T11:00:09.516602 #1913]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/logs/files_logs/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/content_fixity_report.n3 -- Downloading from aip/v1/items/6bb30310-baa2-47f9-8ebc-5246370db71f/filesets/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/fixity ...
I, [2023-04-11T11:00:09.578987 #1913]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/logs/files_logs/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/content_fixity_report.n3 -- Saved
I, [2023-04-11T11:00:09.579166 #1913]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/metadata/files_metadata/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/file_set_metadata.n3 -- Downloading from aip/v1/items/6bb30310-baa2-47f9-8ebc-5246370db71f/filesets/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09 ...
I, [2023-04-11T11:00:09.646511 #1913]  INFO -- : [items - 6bb30310-baa2-47f9-8ebc-5246370db71f]: tmp/work/6bb30310-baa2-47f9-8ebc-5246370db71f/data/objects/metadata/files_metadata/cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09/file_set_metadata.n3 -- Saved
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/container.rb:21: warning: URI.escape is obsolete
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/container.rb:164: warning: URI.escape is obsolete
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/storage_object.rb:257: warning: URI.escape is obsolete
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/storage_object.rb:73: warning: URI.escape is obsolete
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/storage_object.rb:73: warning: URI.escape is obsolete
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/storage_object.rb:73: warning: URI.escape is obsolete
I, [2023-04-11T11:00:10.391924 #1913]  INFO -- : 6bb30310-baa2-47f9-8ebc-5246370db71f was successfully deposited into Swift Storage!
Here are the details of this preservation event:
        UUID: '6bb30310-baa2-47f9-8ebc-5246370db71f'
        Timestamp of Completion: 'Tue, 11 Apr 2023 17:00:11 GMT'
        AIP Checksum: '4305dcd12177496b512ae58ab572f810'
        Metadata: {"project-id"=>"6bb30310-baa2-47f9-8ebc-5246370db71f", "aip-version"=>"1.0", "project"=>"ERA", "promise"=>"bronze"}
        File Details:
                {"fileset_uuid": "cd0c5afb-0c8c-49be-9ede-e4c27d8b3d09",
                "details": {
                        "file_name": "Insight 37_37.pdf",
                        "file_type": "pdf",
                        "file_size": 359732
                }}

/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/storage_object.rb:73: warning: URI.escape is obsolete
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/storage_object.rb:73: warning: URI.escape is obsolete
/usr/lib64/ruby/gems/2.7.0/gems/openstack-3.3.21/lib/openstack/swift/storage_object.rb:73: warning: URI.escape is obsolete
E, [2023-04-11T11:00:10.441705 #1913] ERROR -- : [Rollbar] Tried to send a report with no message, exception or extra data.
E, [2023-04-11T11:00:10.441777 #1913] ERROR -- : nil

The logs file for the above *** pushmi_pullyu.log-20230410.gz ***, and pushmi_pullyu.log (on April 11). Tomorrow, it will probably be rotated into pushmi_pullyu.log-20230412.gz.

Proof of that the item is only preserved into Swift once:

[root@chard log]# cat preservation_events.log | grep 6bb30310-baa2-47f9-8ebc-5246370db71f
I, [2023-04-11T11:00:10.392008 #1913]  INFO -- : 6bb30310-baa2-47f9-8ebc-5246370db71f was successfully deposited into Swift Storage!
        UUID: '6bb30310-baa2-47f9-8ebc-5246370db71f'
        Metadata: {"project-id"=>"6bb30310-baa2-47f9-8ebc-5246370db71f", "aip-version"=>"1.0", "project"=>"ERA", "promise"=>"bronze"}

proof of that the item was attempted many times, (180 log entries for this item)

[root@chard log]# zcat pushmi_pullyu.log-20230410.gz | grep "6bb30310-baa2-47f9-8ebc-5246370db71f" | wc -l
180

@henryzhang87
Copy link
Collaborator Author

there are some other items exhibiting the same patterns of behaviours.

@pgwillia
Copy link
Member

I think there are five situations we've observed that were recorded with MaxDepositAttemptsReached

  1. undefined method `strip' for false:FalseClass
  2. No space left on device @ io_write - /var/pushmi_pullyu/tmp/work/
  3. No space left on device - sendfile
  4. No such file or directory @ rb_sysopen - tmp/work/
  5. Authentication failed with response code 403 OpenStack::Exception::ExpiredAuthToken

The first one is the most common and the one you've described. I can take a look at that one in more detail.

@henryzhang87
Copy link
Collaborator Author

henryzhang87 commented Apr 11, 2023 via email

@pgwillia
Copy link
Member

undefined method strip' for false:FalseClass`

Saving this to come back to later.

Somehow

era_container = swift_connection.container(swift_container)

gets to this
https://github.com/ruby/net-http/blob/542695d02dd7da043e0b26ae4a9922f71f85c1bb/lib/net/http/header.rb#L13-L28

  def initialize_http_header(initheader)
    @header = {}
    return unless initheader
    initheader.each do |key, value|
      warn "net/http: duplicated HTTP header: #{key}", uplevel: 3 if key?(key) and $VERBOSE
      if value.nil?
        warn "net/http: nil HTTP header: #{key}", uplevel: 3 if $VERBOSE
      else
        value = value.strip # raise error for invalid byte sequences
        if value.count("\r\n") > 0
          raise ArgumentError, "header #{key} has field value #{value.inspect}, this cannot include CR/LF"
        end
        @header[key.downcase.to_s] = [value]
      end
    end
  end

via this
https://github.com/ruby-openstack/ruby-openstack/blob/8e735c3d1932365198cf1366fd8175352b8b14d4/lib/openstack/swift/connection.rb#L24-L36

    # Returns an OpenStack::Swift::Container object that can be manipulated easily.
    # Throws a OpenStack::Exception::ItemNotFound if the container doesn't exist.
    #
    #    container = cf.container('test')
    #    container.count
    #    => 2
    #    container = cf.container("no_such_container")
    #    => OpenStack::Exception::ItemNotFound: The resource could not be found
    #
    def container(name)
      OpenStack::Swift::Container.new(self, name)
    end
    alias :get_container :container

https://github.com/ruby-openstack/ruby-openstack/blob/8e735c3d1932365198cf1366fd8175352b8b14d4/lib/openstack/swift/container.rb#L13-L27

    def initialize(swift, name)
      @swift = swift
      @name = name
      @metadata = container_metadata
    end

    # Retrieves Metadata for the container
    def container_metadata
      path = "/#{URI.encode(@name.to_s)}"
      response = @swift.connection.req("HEAD", path)
      resphash = response.to_hash
      meta = {:bytes=>resphash["x-container-bytes-used"][0], :count=>resphash["x-container-object-count"][0], :metadata=>{}}
      resphash.inject({}){|res, (k,v)| meta[:metadata].merge!({ k.gsub("x-container-meta-", "") => v.first }) if k.match(/^x-container-meta-/)}
      meta
    end

https://github.com/ruby-openstack/ruby-openstack/blob/8e735c3d1932365198cf1366fd8175352b8b14d4/lib/openstack/connection.rb#L210-L270

    # This method actually makes the HTTP REST calls out to the server
    def csreq(method,server,path,port,scheme,headers = {},data = nil,attempts = 0, &block) # :nodoc:
      tries = @retries
      time = 3

      request_id = "req-#{SecureRandom.uuid}"
      started_timestamp = Time.now.to_f * 1000
      log_request(request_id, "REQUEST: #{method.to_s} => #{scheme}://#{server}#{path}")
      headers.store('X-Openstack-Request-Id', request_id)

      hdrhash = headerprep(headers)
      start_http(server,path,port,scheme,hdrhash)
      request = Net::HTTP.const_get(method.to_s.capitalize).new(path,hdrhash)
      request.body = data
      response = nil
      @semaphore.synchronize do
        if block_given?
          response =  @http[server].request(request) do |res|
            res.read_body do |b|
              yield b
            end
          end
        else
          response = @http[server].request(request)
        end
      end
      log_request(request_id, "RESPONSE: Code => #{response.code} Time => #{(Time.now.to_f * 1000) - started_timestamp}ms")
      if @is_debug
        puts "REQUEST: #{method.to_s} => #{scheme}://#{server}#{path}"
        puts data if data
        puts "RESPONSE: #{response.body}"
        puts '----------------------------------------'
      end
      raise OpenStack::Exception::ExpiredAuthToken if response.code == "401"
      response
    rescue Errno::EPIPE, Timeout::Error, Errno::EINVAL, EOFError
      # Server closed the connection, retry
      puts "Can't connect to the server: #{tries} tries to reconnect" if @is_debug
      sleep time += 1
      @http[server].finish if @http[server].started?
      retry unless (tries -= 1) <= 0
      raise OpenStack::Exception::Connection, "Unable to connect to #{server} after #{@retries} retries"
    rescue OpenStack::Exception::ExpiredAuthToken
      raise OpenStack::Exception::Connection, "Authentication token expired and you have requested not to retry" if @retry_auth == false
      OpenStack::Authentication.init(self)
      retry
    end

    # This is a much more sane way to make a http request to the api.
    # Example: res = conn.req('GET', "/servers/#{id}")
    def req(method, path, options = {})
      server   = options[:server]   || @service_host
      port     = options[:port]     || @service_port
      scheme   = options[:scheme]   || @service_scheme
      headers  = options[:headers]  || {'content-type' => 'application/json'}
      data     = options[:data]
      attempts = options[:attempts] || 0
      path = (@service_path.empty? ? "/" : @service_path) + @quantum_version.to_s + path
      res = csreq(method,server,path,port,scheme,headers,data,attempts)
      res.code.match(/^20.$/) ? (return res) : OpenStack::Exception.raise_exception(res)
    end

@pgwillia
Copy link
Member

pgwillia commented Apr 13, 2023

#244 (comment)

This looks like it might be a bug in the openstack gem, which is no longer being maintained.

I haven't been able to reproduce it, but it seems like the HTTP headers that are generated one of the values parsed is false when only Strings are expected.

I wonder if this is related to the OpenStack 403 response that occurs before the other failures. It would be great to be able to see the corresponding OpenStack logs.

@pgwillia
Copy link
Member

Is there a difference between writing and creating? Are these all instances of one or the other?

# ruby-openstack expects the header hash in different structure for write vs create_object methods

@henryzhang87
Copy link
Collaborator Author

@pgwillia if it is desired to simulate OpenStack 403, is it possible to use a fake token in the development stack so that the request for a resource will be forbidden? Then we might be able to trace what is the http initheader's key, and why its value is a boolean false instead of a string.

To troubleshoot, I added a line to log the key: value pair in the code of the test server (which is not a good idea to mess up with third party code) as shown below (the line is bold and italicised), and let it run for an extended period of time, unfortunately, the error never happened during that period of time. After that, I removed that line from the third party code.

def initialize_http_header(initheader)
@Header = {}
return unless initheader
initheader.each do |key, value|
warn "net/http: duplicated HTTP header: #{key}", uplevel: 3 if key?(key) and $VERBOSE
if value.nil?
warn "net/http: nil HTTP header: #{key}", uplevel: 3 if $VERBOSE
else
File.write("/var/tmp/strip.log", "#{key} : ${value}",mode:"a")
value = value.strip # raise error for invalid byte sequences
if value.count("\r\n") > 0
raise ArgumentError, "header #{key} has field value #{value.inspect}, this cannot include CR/LF"
end
@Header[key.downcase.to_s] = [value]
end
end
end

Similarly, we can simulate a failed access to Redis queue, and any other factors that might cause problems of PMPY to download and write

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants