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.

Sign up for GitHub

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

Jump to bottom

Web UI: error parsing log message #3694

Closed
mglukhovsky opened this issue Jan 29, 2015 · 11 comments
Closed

Web UI: error parsing log message #3694

mglukhovsky opened this issue Jan 29, 2015 · 11 comments
Assignees
@Tryneus
Labels
tp:bug
Milestone
1.16

Comments

@mglukhovsky
Copy link
Member

A query failed for log entries in the web UI:

Error

The request to retrieve data failed. You can try to refresh.

Error:

Problem with reading log file on server `orpheus_local_2ra`: cannot parse log message (8) in:
r.db("rethinkdb").table("logs", {identifierFormat: "uuid"}).orderBy({index: r.desc("id")}).limit(5).map(function(var_48) { return var_48.merge({server: r.db("rethinkdb").table("server_config").get(var_48("server"))("name"), server_id: var_48("server")}); })
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

The problem persists after refresh.

Running r.db('rethinkdb').table('logs') in the Data Explorer returns:

RqlRuntimeError: Problem with reading log file on server `orpheus_local_2ra`: cannot parse log message (8) in:
r.db("rethinkdb").table("logs")
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
@mglukhovsky
Copy link
Member Author

This error shows anywhere logs are loaded in the web UI.

@coffeemug coffeemug added this to the 1.16.x milestone Jan 29, 2015
@mglukhovsky
Copy link
Member Author

Log file contents:

2015-01-29T04:32:41.211337000 0.005084s notice: Initializing directory /Users/michael/Desktop/1.16/rdb/d2/rethinkdb_data
2015-01-29T04:32:41.211455000 0.005197s notice: Running rethinkdb 1.16.0 (CLANG 6.0 (clang-600.0.56))...
2015-01-29T04:32:41.215674000 0.009417s notice: Running on Darwin 14.0.0 x86_64
2015-01-29T04:32:41.215735000 0.009477s notice: Loading data from directory /Users/michael/Desktop/1.16/rdb/d2/rethinkdb_data
2015-01-29T04:32:41.350523000 0.144265s info: Automatically using cache size of 1164 MB
2015-01-29T04:32:41.351271000 0.145013s notice: Listening for intracluster connections on port 30015
2015-01-29T04:32:41.351364000 0.145106s info: Attempting connection to 1 peer...
2015-01-29T04:32:41.355457000 0.149200s notice: Connected to server "orpheus_local_yt6" f338ceca-62be-4b64-b1dd-11b096cb96ad
2015-01-29T04:32:41.358882000 0.152624s info: Disconnected from server "orpheus_local_yt6" f338ceca-62be-4b64-b1dd-11b096cb96ad
2015-01-29T04:32:41.359643000 0.153385s error: Could not bind to RDB protocol port: The address at localhost:29015 is reserved or already in use.
2015-01-29T04:32:47.841670000 0.004971s notice: Running rethinkdb 1.16.0 (CLANG 6.0 (clang-600.0.56))...
2015-01-29T04:32:47.844907000 0.008205s notice: Running on Darwin 14.0.0 x86_64
2015-01-29T04:32:47.844937000 0.008233s notice: Loading data from directory /Users/michael/Desktop/1.16/rdb/d2/rethinkdb_data
2015-01-29T04:32:47.885973000 0.049270s info: Automatically using cache size of 1161 MB
2015-01-29T04:32:47.886544000 0.049841s notice: Listening for intracluster connections on port 31015
2015-01-29T04:32:47.886637000 0.049935s info: Attempting connection to 1 peer...
2015-01-29T04:32:47.888408000 0.051705s notice: Connected to server "orpheus_local_yt6" f338ceca-62be-4b64-b1dd-11b096cb96ad
2015-01-29T04:32:47.889195000 0.052492s notice: Listening for client driver connections on port 30015
2015-01-29T04:32:47.889283000 0.052580s notice: Listening for administrative HTTP connections on port 10080
2015-01-29T04:32:47.889285000 0.052599s notice: Listening on addresses: 127.0.0.1, ::1
2015-01-29T04:32:47.889311000 0.052607s notice: To fully expose RethinkDB on the network, bind to all addresses by running rethinkdb with the `--bind all` command line option.
2015-01-29T04:32:47.889317000 0.052614s notice: Server ready, "orpheus_local_2ra" 55192768-78ce-4419-b0f7-9bcb36d3d85c
2015-01-29T04:33:02.223680000 14.386086s notice: Connected to server "orpheus_local_l7e" 6d01131d-8887-4235-b9ff-3b9b6b716ece
2015-01-29T04:33:02.224185000 14.386591s info: Disconnected from server "orpheus_local_l7e" 6d01131d-8887-4235-b9ff-3b9b6b716ece
2015-01-29T04:33:07.836940000 19.999027s notice: Connected to server "orpheus_local_ol3" a8ab27f1-48bc-4f39-9fa2-2e41ba5f96cc
2015-01-29T04:33:07.891232000 20.053319s warn: Received invalid clustering header from (unknown), closing connection -- something might be connecting to the wrong port.
2015-01-29T04:33:07.891702000 20.053789s warn: Received invalid clustering header from (unknown), closing connection -- something might be connecting to the wrong port.
2015-01-29T04:33:10.760254000 22.922151s warn: Received invalid clustering header from (unknown), closing connection -- something might be connecting to the wrong port.
2015-01-29T04:33:10.760652000 22.922548s warn: Received invalid clustering header from (unknown), closing connection -- something might be connecting to the wrong port.
2015-01-29T04:33:13.232863000 25.394633s notice: Server got SIGINT from pid 303, uid 501; shutting down...
2015-01-29T04:33:13.232975000 25.394744s notice: Shutting down client connections...
2015-01-29T04:33:13.233106000 25.394875s notice: All client connections closed.
2015-01-29T04:33:13.233115000 25.394884s notice: Shutting down storage engine... (This may take a while if you had a lot of unflushed data in the writeback cache.)
2015-01-29T04:33:13.233535000 25.395304s notice: Storage engine shut down.
2015-01-29T04:33:13.233935000 25.395704s info: Disconnected from server "orpheus_local_yt6" f338ceca-62be-4b64-b1dd-11b096cb96ad
2015-01-29T04:33:13.234109000 25.395878s info: Disconnected from server "orpheus_local_ol3" a8ab27f1-48bc-4f39-9fa2-2e41ba5f96cc
2015-01-29T04:33:31.260927000 0.005074s notice: Running rethinkdb 1.16.0 (CLANG 6.0 (clang-600.0.56))...
2015-01-29T04:33:31.264697000 0.008840s notice: Running on Darwin 14.0.0 x86_64
2015-01-29T04:33:31.264753000 0.008895s notice: Loading data from directory /Users/michael/Desktop/1.16/rdb/d2/rethinkdb_data
2015-01-29T04:33:31.309545000 0.053687s info: Automatically using cache size of 1189 MB
2015-01-29T04:33:31.310161000 0.054303s notice: Listening for intracluster connections on port 31015
2015-01-29T04:33:31.310231000 0.054372s info: Attempting connection to 1 peer...
2015-01-29T04:33:31.312146000 0.056288s notice: Connected to server "orpheus_local_yt6" f338ceca-62be-4b64-b1dd-11b096cb96ad
2015-01-29T04:33:31.312702000 0.056844s notice: Listening for client driver connections on port 30015
2015-01-29T04:33:31.312859000 0.057001s notice: Listening for administrative HTTP connections on port 10080
2015-01-29T04:33:31.312867000 0.057009s notice: Listening on addresses: 127.0.0.1, ::1
2015-01-29T04:33:31.312868000 0.057010s notice: To fully expose RethinkDB on the network, bind to all addresses by running rethinkdb with the `--bind all` command line option.
2015-01-29T04:33:31.312872000 0.057014s notice: Server ready, "orpheus_local_2ra" 55192768-78ce-4419-b0f7-9bcb36d3d85c
2015-01-29T04:34:08.404997000 37.146911s notice: Connected to server "orpheus_local_pq8" 7a8005d6-60cc-46e0-aec7-ed3fe6efc254
2015-01-29T04:34:08.405471000 37.147385s info: Disconnected from server "orpheus_local_pq8" 7a8005d6-60cc-46e0-aec7-ed3fe6efc254
2015-01-29T04:34:43.231055000 71.970868s info: Disconnected from server "orpheus_local_yt6" f338ceca-62be-4b64-b1dd-11b096cb96ad
2015-01-29T04:34:56.077467000 84.816516s notice: Connected to server "orpheus_local_yt6" f338ceca-62be-4b64-b1dd-11b096cb96ad
2015-01-29T04:36:02.716851000 151.451825s notice: Connected to server "orpheus_local_1ts" 8a19b7e0-9f99-4ba1-bc8a-5e3ef43dc7df
2015-01-29T04:36:11.392170000 160.126635s notice: Connected to server __deleted_server__ a8ab27f1-48bc-4f39-9fa2-2e41ba5f96cc
2015-01-29T04:36:15.694558000 164.428768s info: Disconnected from server __deleted_server__ a8ab27f1-48bc-4f39-9fa2-2e41ba5f96cc
2015-01-29T04:36:21.602490000 170.336382s notice: Connected to server "orpheus_local_051" 4686cdd4-883f-4511-abfc-a9bba262045b

@deontologician
Copy link
Contributor

I got this in testing, but we weren't able to reproduce it because I stupidly deleted my log file. Ping @timmaxw

@danielmewes
Copy link
Member

Oh no. @mglukhovsky If possible please make a copy from the log file as well.

@danielmewes
Copy link
Member

@mglukhovsky Never mind, can reproduce with the data you posted above.

@danielmewes
Copy link
Member

The file_reverse_reader_t is giving us these two lines as one:

2015-01-29T04:33:13.233935000 25.395704s info: Disconnected from server "orpheus_local_yt6" f338ceca-62be-4b64-b1dd-11b096cb96ad
2015-01-29T04:33:13.234109000 25.395878s info: Disconnected from server "orpheus_local_ol3" a8ab27f1-48bc-4f39-9fa2-2e41ba5f96cc

@danielmewes
Copy link
Member

This goes away if I for example increase the file_reverse_reader_t::chunk_size from 4096 to 4097.
If I then add a single character to some log message at the beginning of the file, it appears again.
Probably a bug if a newline falls exactly onto a chunk boundary or something like that.

I think this is not a new bug.
The latest modification to file_reverse_reader_t as far as I can see was 2d83a67 which is already in 1.15.0 and onwards.

When the error shows up, it's more visible in the new web UI with ReQL admin. Previously it seems like if a log entry was illegal, all log entries would simply appear as blank. Now we get a very visible ReQL error message.

Re-assigning to @Tryneus since you were the last to work with the file.

@danielmewes danielmewes assigned Tryneus and unassigned timmaxw Jan 29, 2015
@mglukhovsky
Copy link
Member Author

As a side note, I'd add that I had some serious weirdness going on when I was first trying to setup the cluster -- each server had very different port offsets given as command-line flags, but a few of them reported as connecting on the wrong intracluster port and showed up as ghost servers in the web UI and had to have their rethinkdb_data directories deleted.

However, I think that was unrelated. I also couldn't reproduce this, so I chalked it up to gremlins.

@mglukhovsky
Copy link
Member Author

I also have the log file in Dropbox to share if we need it (but I think @danielmewes nailed it). This should go in a point release, but again, couldn't reproduce easily.

@Tryneus
Copy link
Member

Tryneus commented Jan 29, 2015

Fix is up in review 2551, mostly just an off-by-one error.

danielmewes pushed a commit that referenced this issue Jan 29, 2015
Added #3694 to 1.16 release notes.
c9ad73b
@danielmewes danielmewes mentioned this issue Jan 29, 2015
Merged
@Tryneus
Copy link
Member

Tryneus commented Jan 29, 2015

The fix has been approved and merged to next in commit f23c1b0, and cherry-picked into v1.16.x in commit a98c4bf. Will be in release 1.16.0.

@Tryneus Tryneus closed this as completed Jan 29, 2015
@danielmewes danielmewes modified the milestones: 1.16, 1.16.x Jan 30, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Tryneus Tryneus

Labels
tp:bug
Projects
None yet
Milestone
1.16
Development

No branches or pull requests
6 participants
@deontologician @coffeemug @mglukhovsky @timmaxw @danielmewes @Tryneus