Re: [etch-users] How can I debug what happens on Etch server when a client does --list-files

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 422-6466

An update on this,

I updated to libxml-ruby-v2.0.6, and now the issue is a little different.  After I start the server, I can serve one request, and then I get a segfault.  I just started up the server, and I run the first request, which is "etch -n --debug /etc/issue.net".  The output on the server is the facter load, and this at the end:

  Fact Load (9.6ms)   SELECT * FROM "facts" WHERE ("facts"."client_id" = 1)
  Original Load (0.3ms)   SELECT * FROM "originals" WHERE ("originals"."client_id" = 1 AND "originals"."file" = '/etc/issue.net') LIMIT 1
  EtchConfig Load (0.3ms)   SELECT * FROM "etch_configs" WHERE ("etch_configs"."client_id" = 1 AND "etch_configs"."file" = '/etc/issue.net') LIMIT 1
Completed in 873ms (View: 1, DB: 40) | 200 OK [http://etch.sys.comcast.net/files]

Here is what the client sees, after the big hash of facts:

Response from server:
'<?xml version="1.0" encoding="UTF-8"?>
<files>
  <configs>
    <config filename="/etc/issue.net">
        <file>
                <!--
                        By default files will be owned by root,
                        but you can change that.  If this user or
                        group doesn't exist UID 0 and GID 0 will
                        be used as a faillback.
                  -->
                <owner>root</owner>
                <group>sys</group>
                <perms>644</perms>

        <contents>KioqKioqKioqKioqKioqKioqKioqKioqKioqKioqKioqKioqKioqKioqKioq
KioqKioqKioqKioKV0FSTklORzoKICAgIAogIFRoaXMgc3lzdGVtICBpcyBz
b2xlbHkgZm9yICB0aGUgdXNlIG9mIGF1dGhvcml6ZWQgIENvbWNhc3QgZW1w
bG95ZWVzCiAgYW5kIGNvbnRyYWN0b3JzLgogICAgCiAgQ29tY2FzdCAgcmVz
ZXJ2ZXMgdGhlIHJpZ2h0ICBhdCBhbnkgIHRpbWUgdG8gIG1vbml0b3IgdXNh
Z2UgIG9mIHRoaXMKICBzeXN0ZW0gdG8gZW5zdXJlIGNvbXBsaWFuY2Ugd2l0
aCB0aGlzIHBvbGljeSwgYWxsIGFwcGxpY2FibGUgQ29tY2FzdAogIHBvbGlj
aWVzIHRoYXQgYXBwbHkgdG8gZWxlY3Ryb25pYyBjb21tdW5pY2F0aW9ucywg
YW5kIGFsbCBhcHBsaWNhYmxlCiAgbGF3cy4KICAgIAogIFlvdXIgdXNlIG9m
IHRoaXMgc3lzdGVtIGNvbnN0aXR1dGVzIHlvdXIgYWNjZXB0YW5jZSBvZiBh
bmQgYWdyZWVtZW50CiAgdG8gYWxsICBhcHBsaWNhYmxlIENvbWNhc3QgZWxl
Y3Ryb25pYyAgY29tbXVuaWNhdGlvbnMgcG9saWNpZXMsIHlvdXIKICBjb25z
ZW50IHRvIG1vbml0b3JpbmcgYnkgQ29tY2FzdCwgIGFuZCB5b3VyIGV4cHJl
c3MgYWdyZWVtZW50IHRvIHVzZQogIHRoaXMgc3lzdGVtIGluIGNvbXBsaWFu
Y2Ugd2l0aCBhbGwgYXBwbGljYWJsZSBsYXdzLgogICAgCiAgQW55IHVuYXV0
aG9yaXplZCAgdXNlIG9mIG9yICBhY2Nlc3MgdG8gdGhpcyAgc3lzdGVtIG1h
eSByZXN1bHQgIGluIGEKICByZXZvY2F0aW9uIG9mIHlvdXIgdXNlciAgcHJp
dmlsZWdlcywgb3RoZXIgZGlzY2lwbGluYXJ5IGFjdGlvbiB1cCB0bwogIGFu
ZCBpbmNsdWRpbmcgdGVybWluYXRpb24gb2YgZW1wbG95bWVudCBvciBjb250
cmFjdCwgb3IgcmVmZXJyYWxzIHRvCiAgbGF3IGVuZm9yY2VtZW50ICBvZmZp
Y2lhbHMgaW5jbHVkaW5nICB0aGUgcHJvdmlzaW9uIGV2aWRlbmNlICBvZiBh
bnkKICB1bmF1dGhvcml6ZWQgdXNlIG9yIGFjY2VzcyB0byBsYXcgZW5mb3Jj
ZW1lbnQuCioqKioqKioqKioqKioqKioqKioqKioqKioqKioqKioqKioqKioq
KioqKioqKioqKioqKioqKioqKioqKioqIAoK
</contents></file>
</config>
  </configs>
  <allcommands/>
  <retrycommands/>
</files>
'
Processing config for /etc/issue.net
Processing /etc/issue.net
No change to /etc/issue.net necessary

Then I run the same command again exactly as before.  Here is what the server logs see:

/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/libxml-ruby-2.0.6/lib/libxml/node.rb:61: [BUG] Segmentation fault
ruby 1.8.7 (2011-02-18 patchlevel 334) [x86_64-linux], MBARI 0x6770, Ruby Enterprise Edition 2011.03

E, [2011-05-26T17:26:34.509706 #2212] ERROR -- : reaped #<Process::Status: pid=2213,signaled(SIGIOT=6)> worker=0
Exception `Errno::ECHILD' at /opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:401 - No child processes
I, [2011-05-26T17:26:34.509984 #2212]  INFO -- : worker=0 spawning...

Here is what the client sees, after the hash of facts:

end of file reached
/opt/comcast/platform/etch/lib/ruby/1.8/net/protocol.rb:135:in `sysread'
/opt/comcast/platform/etch/lib/ruby/1.8/net/protocol.rb:135:in `rbuf_fill'
/opt/comcast/platform/etch/lib/ruby/1.8/timeout.rb:67:in `timeout'
/opt/comcast/platform/etch/lib/ruby/1.8/timeout.rb:101:in `timeout'
/opt/comcast/platform/etch/lib/ruby/1.8/net/protocol.rb:134:in `rbuf_fill'
/opt/comcast/platform/etch/lib/ruby/1.8/net/protocol.rb:116:in `readuntil'
/opt/comcast/platform/etch/lib/ruby/1.8/net/protocol.rb:126:in `readline'
/opt/comcast/platform/etch/lib/ruby/1.8/net/http.rb:2028:in `read_status_line'
/opt/comcast/platform/etch/lib/ruby/1.8/net/http.rb:2017:in `read_new'
/opt/comcast/platform/etch/lib/ruby/1.8/net/http.rb:1051:in `request'
/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/etch-3.19.0/lib/etchclient.rb:339:in `process_until_done'
/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/etch-3.19.0/lib/etchclient.rb:312:in `times'
/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/etch-3.19.0/lib/etchclient.rb:312:in `process_until_done'
/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/etch-3.19.0/lib/etchclient.rb:240:in `catch'
/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/etch-3.19.0/lib/etchclient.rb:240:in `process_until_done'
/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/etch-3.19.0/bin/etch:109
/opt/comcast/etch/bin/etch:19:in `load'
/opt/comcast/etch/bin/etch:19

So, what can I do from here?

Thanks,

--N.

On May 25, 2011, at 3:16 PM, Johnston, Nathaniel wrote:

EtchMen,

I am having an issue where I see the Etch server segfaulting each time I try and run Etch, even if I use the --list-files or the --dry-run methods.  Here's how it happens.  First, I start up the Etch server.  Here is what it outputs on startup:

# unicorn_rails -d -p 38240
{:daemonize=>false,
 :app=>
  #<Proc:0x000000000eaf56c8@/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/unicorn-3.6.2/bin/unicorn_rails:135>,
 :unicorn_options=>{:listeners=>[]}}
Exception `Errno::EEXIST' at /opt/comcast/platform/etch/lib/ruby/1.8/fileutils.rb:243 - File exists - tmp/cache
Exception `Errno::EEXIST' at /opt/comcast/platform/etch/lib/ruby/1.8/fileutils.rb:243 - File exists - tmp/pids
Exception `Errno::EEXIST' at /opt/comcast/platform/etch/lib/ruby/1.8/fileutils.rb:243 - File exists - tmp/sessions
Exception `Errno::EEXIST' at /opt/comcast/platform/etch/lib/ruby/1.8/fileutils.rb:243 - File exists - tmp/sockets
I, [2011-05-25T19:11:33.677699 #19746]  INFO -- : listening on addr=0.0.0.0:38240 fd=3
I, [2011-05-25T19:11:33.677935 #19746]  INFO -- : worker=0 spawning...
I, [2011-05-25T19:11:33.678549 #19746]  INFO -- : master process ready
Exception `NameError' at /opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:499 - uninitialized constant Unicorn::HttpServer::OpenSSL
I, [2011-05-25T19:11:33.679040 #19747]  INFO -- : worker=0 spawned pid=19747
I, [2011-05-25T19:11:33.679169 #19747]  INFO -- : Refreshing Gem list
Exception `NoMethodError' at /opt/comcast/platform/etch/lib/ruby/1.8/rational.rb:82 - undefined method `gcd' for Rational(1, 2):Rational
Exception `Gem::LoadError' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems.rb:274 - can't activate activerecord (~> 2.3.11, runtime) for ["searchlogic-2.5.6"], already activated activerecord-2.3.8 for ["rails-2.3.8"]
Exception `Gem::LoadError' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems.rb:861 - RubyGem version error: builder(3.0.0 not ~> 2.1.2)

Exception `TypeError' at (eval):4 - can't modify frozen object
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:29 - no such file to load -- fast_xs
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:29 - no such file to load -- json
Using Ext extension for JSON.
Exception `Gem::LoadError' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems.rb:861 - Could not find RubyGem activerecord-sqlite3-adapter (>= 0)

Exception `NameError' at /opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/activesupport-2.3.8/lib/active_support/dependencies.rb:443 - uninitialized constant ActionDispatch
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:29 - no such file to load -- ruby-debug
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:29 - no such file to load -- classtree
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:35 - no such file to load -- classtree
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/activesupport-2.3.8/lib/active_support/dependencies.rb:162 - no such file to load -- classtree
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:29 - no such file to load -- methodsig
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:35 - no such file to load -- methodsig
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/activesupport-2.3.8/lib/active_support/dependencies.rb:162 - no such file to load -- methodsig
=> Debugger enabled
worker=0 ready

I run a simple command on the etch client, which seems to bomb, although the error messaging is enigmatic:

[root@jumphst-ch-2p tmp]# etch /etc/yum.conf
Saving temporary copy of original file:  /etc/yum.conf -> /var/etch/orig/etc/yum.conf.TMP
1 block
end of file reached

Etch server segfaults.  Here is what it says, although I cut the output off for brevity when it was restating messages from the startup block of logs, above.

Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:29 - no such file to load -- sqlite3
Exception `MissingSourceFile' at /opt/comcast/platform/etch/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:29 - no such file to load -- libxml
/opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/libxml-ruby-1.1.2/lib/libxml/node.rb:57: [BUG] Segmentation fault
ruby 1.8.7 (2011-02-18 patchlevel 334) [x86_64-linux], MBARI 0x6770, Ruby Enterprise Edition 2011.03

E, [2011-05-25T19:12:23.940838 #19746] ERROR -- : reaped #<Process::Status: pid=19756,signaled(SIGIOT=6)> worker=0
Exception `Errno::ECHILD' at /opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:401 - No child processes
I, [2011-05-25T19:12:23.941145 #19746]  INFO -- : worker=0 spawning...
Exception `NameError' at /opt/comcast/platform/etch/lib/ruby/gems/1.8/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:499 - uninitialized constant Unicorn::HttpServer::OpenSSL
I, [2011-05-25T19:12:23.942207 #19758]  INFO -- : worker=0 spawned pid=19758
I, [2011-05-25T19:12:23.942324 #19758]  INFO -- : Refreshing Gem list

Here is the output of `gem list --local`:

*** LOCAL GEMS ***

actionmailer (2.3.8)
actionpack (2.3.8)
activerecord (2.3.11, 2.3.8)
activeresource (2.3.8)
activesupport (2.3.11, 2.3.8)
builder (3.0.0)
bundler (1.0.13)
columnize (0.3.2)
etch (3.19.0)
facter (1.5.8)
fast_xs (0.8.0)
gem2rpm (0.6.0)
i18n (0.6.0)
json (1.5.1)
kgio (2.4.0)
libxml-ruby (1.1.2)
linecache (0.43)
memcache-client (1.8.5)
nokogiri (1.4.4)
rack (1.1.2)
rails (2.3.8)
rake (0.8.7)
ruby-debug (0.10.4)
ruby-debug-base (0.10.4)
searchlogic (2.5.6)
sqlite3-ruby (1.2.5)
tmail (1.2.7.1)
tzinfo (0.3.27)
unicorn (3.6.2)
will_paginate (2.3.15)

--N.
------------------------------------------------------------------------------
vRanger cuts backup time in half-while increasing security.
With the market-leading solution for virtual backup and recovery,
you get blazing-fast, flexible, and affordable data protection.
Download your free trial now.
http://p.sf.net/sfu/quest-d2dcopy1_______________________________________________
etch-users mailing list
etc...@li...
https://lists.sourceforge.net/lists/listinfo/etch-users